read_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

// read_lock_timing.C - Tool for reading and analyzing the
// repository's StableLock/VolatileRootLock/userGroup_lock timing.

#include "read_timing_common.H"

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

#include <unistd.h>
#include <Atom.H>

#include <list>

using std::ostream;
using std::ofstream;
using std::cout;
using std::cerr;
using std::endl;
using std::list;
using Basics::OBufStream;

enum which_lock_t
  {
    stable,
    volatileRoot,
    userGroup
  };

void print_timeval(ostream &out, const struct timeval time)
{
  time_t temp_secs = time.tv_sec;
  struct tm split_time;
  (void) localtime_r(&temp_secs, &split_time);
  char time_str_buf[512];
  strftime(time_str_buf, sizeof(time_str_buf),
           "%Y-%m-%d %H:%M:%S", &split_time);
  
  out << time_str_buf << " +" << (((double) time.tv_usec) / 1000) << " ms";
}

ostream &operator<<(ostream &out, const struct timeval time)
{
  print_timeval(out, time);
  return out;
}

struct Lock_Data
{
  struct FileFormatError {};
  which_lock_t lock;
  struct timeval start_time;
  Delta_Time time_to_acquire;
  bool acquired;
  bool write;
  Delta_Time time_held;
  Delta_Time time_to_release;
  Atom *reason;

  Lock_Data(which_lock_t lock)
    : lock(lock), reason(0)
  {
  }

  void read_start_time(FILE *input) throw(FS::EndOfFile)
  {
    // Start time
    unsigned int start_secs, start_usecs;
    size_t n_read =
      fread((void *) &start_secs, sizeof(unsigned int), 1, input);
    if(n_read < 1)
      {
        throw FS::EndOfFile();
      }
    assert(n_read == 1);
    n_read =
      fread((void *) &start_usecs, sizeof(unsigned int), 1, input);
    if(n_read < 1)
      {
        throw FS::EndOfFile();
      }
    assert(n_read == 1);

    start_time.tv_sec = start_secs;
    start_time.tv_usec = start_usecs;
  }

  void read_reason(FILE *input) throw(FS::EndOfFile)
  {
    char small_buf[1024];
    char *cur_buf = small_buf;
    unsigned int cur_buf_size = sizeof(small_buf);
    unsigned int buf_pos = 0;
    int next_char;
    while((next_char = getc(input)) != EOF)
      {
        // Expand buffer if needed
        if(buf_pos >= cur_buf_size)
          {
            cur_buf_size *= 2;
            char * new_buf =  NEW_PTRFREE_ARRAY(char, cur_buf_size);
            memcpy(new_buf, cur_buf, buf_pos);
            cur_buf = new_buf;
          }
        cur_buf[buf_pos++] = next_char;
        if(next_char == 0)
          break;
      }

    reason = NEW_CONSTR(Atom, (cur_buf));
  }

  bool read_record(FILE *input) throw(FS::EndOfFile, FileFormatError)
  {
    bool result = false;
    int record_byte = getc(input);
    switch(record_byte)
      {
      case 1:
        // acquireRead start
        write = false;
        read_start_time(input);
        break;
      case 2:
        // acquireRead completed
        acquired = true;
        time_to_acquire.read(input);
        break;
      case 3:
        // tryRead failed
        acquired = false;
        result = true;
        time_to_acquire.read(input);
        break;
      case 4:
        // acquireWrite start
        write = true;
        read_start_time(input);
        break;
      case 5:
        // acquireWrite completed
        acquired = true;
        time_to_acquire.read(input);
        break;
      case 6:
        // tryWrite failed
        acquired = false;
        result = true;
        time_to_acquire.read(input);
        break;
      case 7:
        // release start
        time_held.read(input);
        break;
      case 8:
        // release completed
        result = true;
        time_to_release.read(input);
        break;
      case 9:
        // reason
        read_reason(input);
        break;
      default:
        // WTF?
        throw FileFormatError();
      }

    return result;
  }

  void print_lock_info(ostream &out, const char *indent,
                       const struct timeval *beginning = 0) const
  {
    out << indent;
    switch(lock)
      {
      case stable:
        out << "StableLock.";
        break;
      case volatileRoot:
        out << "VolatileRootLock.";
        break;
      case userGroup:
        out << "userGroup_lock.";
        break;
      }
    out << (acquired?"acquire":"try") << (write?"Write":"Read") << "():"
        << endl;
    if(beginning != 0)
      {
        if(start_time < *beginning)
          {
            Delta_Time start_delta = (*beginning - start_time);
            out << indent << "  start:        -" << start_delta.msecs()
                << " ms" << endl;
          }
        else
          {
            Delta_Time start_delta = (start_time - *beginning);
            out << indent << "  start:        " << start_delta.msecs()
                << " ms" << endl;
          }
      }
    else
      {
        out << indent << "  start:        " << start_time << endl;
      }
    out << indent << "  acquire time: " << time_to_acquire.msecs() << " ms"
        << endl;
    if(acquired)
      {
        out 
          << indent << "  hold time:    " << time_held.msecs() << " ms" << endl
          << indent << "  release time: " << time_to_release.msecs() << " ms"
          << endl;
      }
    if(reason != 0)
      {
        out
          << indent << "  reason:       " << reason->cchars() << endl;
      }
  }

  void plot_lock_info(unsigned int x_val,
                      ostream &acquire_stream,
                      ostream &hold_stream,
                      ostream &release_stream,
                      const struct timeval &beginning) const
  {
    double my_acquire_start;
    if(start_time < beginning)
      {
        Delta_Time start_delta = (beginning - start_time);
        my_acquire_start = -(start_delta.msecs());
      }
    else
      {
        Delta_Time start_delta = (start_time - beginning);
        my_acquire_start = start_delta.msecs();
      }

    double my_acquire_delta = time_to_acquire.msecs();
    double my_hold_start = (my_acquire_start + my_acquire_delta);
    double my_hold_delta = time_held.msecs();
    double my_release_start = (my_hold_start + my_hold_delta);
    double my_release_delta = time_to_release.msecs();

    // Each of the data files gets four columns:
    // 1: X value
    // 2: Y center point
    // 3: Y min
    // 4: Y max

    acquire_stream << x_val << " "
                   << (my_acquire_start + (my_acquire_delta/2)) << " "
                   << my_acquire_start << " "
                   << my_hold_start << endl;

    if(acquired)
      {
        hold_stream << x_val << " "
                    << (my_hold_start + (my_hold_delta/2)) << " "
                    << my_hold_start << " "
                    << my_release_start << endl;

        release_stream << x_val << " "
                       << (my_release_start + (my_release_delta/2)) << " "
                       << my_release_start << " "
                       << (my_release_start + my_release_delta) << endl;
      }
  }

  bool operator<=(const Lock_Data & other) const
  {
    // Earlier start time: we're lesser
    if(this->start_time < other.start_time)
      {
        return true;
      }
    // Same start time: compare acquire times
    if(this->start_time == other.start_time)
      {
        return (other.time_to_acquire >= this->time_to_acquire);
      }

    return false;
  }
};

typedef list<const Lock_Data *,
             Basics::Allocator<Lock_Data *> > Lock_Event_List;

void sorted_lock_insert(Lock_Event_List &lock_list,
                        const Lock_Data *lock)
{
  assert(lock != 0);

  for(Lock_Event_List::iterator it = lock_list.begin();
      it != lock_list.end();
      it++)
    {
      // Found it's place: insert it here and return.
      if(*lock <= *(*it))
        {
          lock_list.insert(it, lock);
          return;
        }
    }

  // Didn't find a place for this one: add it to the end.
  lock_list.push_back(lock);
}

// This class represents sets of ranges of time.  These are used to
// collect the times during which some particular event occurs so that
// it's possible to locate other events that overlap in time with the
// event of interest.

struct Time_Ranges
{
  struct time_range
  {
    struct timeval start_time, end_time;
    time_range()
    {
      start_time.tv_sec = 0;
      start_time.tv_usec = 0;
      end_time.tv_sec = 0;
      end_time.tv_usec = 0;
    }
    time_range(const struct timeval &start, const Delta_Time &delta)
      : start_time(start), end_time(start + delta)
    {
    }
    time_range(const struct time_range &other)
    {
      start_time.tv_sec = other.start_time.tv_sec;
      start_time.tv_usec = other.start_time.tv_usec;
      end_time.tv_sec = other.end_time.tv_sec;
      end_time.tv_usec = other.end_time.tv_usec;
    }

    inline bool overlaps_end_of(const struct time_range &other) const throw()
    {
      return ((this->start_time <= other.end_time) &&
              (other.end_time <= this->end_time));
    }

    inline bool overlaps_start_of(const struct time_range &other) const throw()
    {
      return ((this->start_time <= other.start_time) &&
              (other.start_time <= this->end_time));
    }

    inline bool contains(const struct time_range &other) const throw()
    {
      return overlaps_end_of(other) && overlaps_start_of(other);
    }

    inline bool contained_by(const struct time_range &other) const throw()
    {
      return other.contains(*this);
    }

    time_range &operator=(const struct time_range &other)
    {
      start_time.tv_sec = other.start_time.tv_sec;
      start_time.tv_usec = other.start_time.tv_usec;
      end_time.tv_sec = other.end_time.tv_sec;
      end_time.tv_usec = other.end_time.tv_usec;

      return *this;
    }

    struct time_range merge(const struct time_range &other)
    {
      struct time_range result;

      // When merging, there should be some overlap.
      assert(this->overlaps_end_of(other) ||
             this->overlaps_start_of(other) ||
             other.overlaps_end_of(*this) ||
             other.overlaps_start_of(*this));

      if(other.start_time < this->start_time)
        {
          result.start_time = other.start_time;
        }
      else
        {
          result.start_time = this->start_time;
        }

      if(other.end_time < this->end_time)
        {
          result.end_time = this->end_time;
        }
      else
        {
          result.end_time = other.end_time;
        }

      return result;
    }
  };

  typedef list<time_range> time_range_list;
  time_range_list ranges;

  // Add a time range to this set
  void add_range(const struct timeval &start, const Delta_Time &delta)
  {
    time_range new_range(start, delta);

    bool added = false;

    for(time_range_list::iterator it = ranges.begin();
        !added && (it != ranges.end());
        it++)
      {
        // Overlaps the end of current item: merge with current item.
        // (Note that this includes the case where the new range
        // completely contains the current range.
        if(new_range.overlaps_end_of(*it))
          {
            time_range merged = (*it).merge(new_range);
            *it = merged;
            added = true;

            // Check new range for overlap with following ranges
            bool done = false;
            while(1)
              {
                time_range_list::iterator it_next = it;
                it_next++;
                if(it_next == ranges.end())
                  {
                    break;
                  }

                if((*it).overlaps_start_of(*it_next))
                  {
                    if(!(*it).overlaps_end_of(*it_next))
                      {
                        // Partial overlap: merge before erasing.
                        merged = (*it).merge(*it_next);
                        *it = merged;
                      }
                    ranges.erase(it_next);
                  }
                else
                  {
                    // Invariant: non-verlapping ranges are sequential
                    assert((*it).end_time < (*it_next).start_time);
                    break;
                  }
              }
          }
        // Overlaps with the start of current item: merge with
        // current.
        else if(new_range.overlaps_start_of(*it))
          {
            time_range merged = (*it).merge(new_range);
            *it = merged;
            added = true;

            // Note: don't need to check for overlap with previous
            // ranges, becuase if the new range overlapped with
            // them, it would have been merged with them.
          }
        // Completely contained by an existing range: do nothing.
        else if(new_range.contained_by(*it))
          {
            added = true;
          }
        // Earlier start than current item but no overlap: insert
        // before current item.
        else if(new_range.start_time < (*it).start_time)
          {
            ranges.insert(it, new_range);
            added = true;
          }
        else
          {
            // If we fall through to here, the new range must start
            // after the end of the current range.
            assert((*it).end_time < new_range.start_time);
          }
      }

    // Not placed before or merged with any existing item: insert it
    // at the end.
    if(!added)
      {
        ranges.push_back(new_range);
      }
  }

  // Test whether a time range overlaps any part of this set.
  bool in_range(const struct timeval &start, const Delta_Time &delta,
                unsigned int &index)
  {
    if(ranges.empty())
      return false;

    time_range test_range(start, delta);

    // Find our starting position, which may be somewhere in the
    // middle.
    time_range_list::iterator it = ranges.begin();
    for(unsigned int i = 0; i < index; i++)
      {
        it++;
        if(it == ranges.end())
          return false;
      }

    // Loop over the remaining ranges looking for one that this event
    // falls in.
    while(it != ranges.end())
      {
        // Have to test for overlaps in both directions, as either
        // could be contained by the other.
        if(test_range.overlaps_start_of(*it) ||
           test_range.overlaps_end_of(*it) ||
           (*it).overlaps_start_of(test_range) ||
           (*it).overlaps_end_of(test_range))
          {
            return true;
          }
        else
          {
            // Time ranegs must be disjoint
            assert((test_range.end_time < (*it).start_time) ||
                   ((*it).end_time < test_range.start_time));
          }

        // Increment ourselves through the list of ranges.
        it++; index++;
      }

    // Didn't find an overlap: not in the set.
    return false;
  }

  void print(ostream &out, const char *indent,
             const Lock_Event_List *events = 0) const
  {
    unsigned int index = 0;
    for(time_range_list::const_iterator it = ranges.begin();
        it != ranges.end();
        it++, index++)
      {
        Delta_Time duration = ((*it).end_time - (*it).start_time);
        out << indent << "range " << index << ":" << endl
            << indent << "  start:    " << (*it).start_time << endl
            << indent << "  end:      " << (*it).end_time << endl
            << indent << "  duration: " << duration.msecs() << " ms" << endl;

        if(events != 0)
          {
            out << endl;
            Text sub_indent(indent);
            sub_indent += "  ";
            for(Lock_Event_List::const_iterator event_it =
                  events[index].begin();
                event_it != events[index].end();
                event_it++)
              {
                (*event_it)->print_lock_info(out, sub_indent.cchars(),
                                             &((*it).start_time));
              }
          }
      }
  }

  void gen_plot(const Text &title_prefix,
                const Text &basename,
                const Lock_Event_List *events) const
  {
    unsigned int index = 0;
    for(time_range_list::const_iterator it = ranges.begin();
        it != ranges.end();
        it++, index++)
      {
        char range_buf[30];
        sprintf(range_buf, "_range%04d", index);
        Text ranage_base = basename+range_buf;
        Text cmd_fname = ranage_base+".gnuplot";
        Text img_name = ranage_base+".png";

        Text ar_data_fname = ranage_base+"_acquireRead.dat";
        Text hr_data_fname = ranage_base+"_holdRead.dat";
        Text rr_data_fname = ranage_base+"_releaseRead.dat";
        Text aw_data_fname = ranage_base+"_acquireWrite.dat";
        Text hw_data_fname = ranage_base+"_holdWrite.dat";
        Text rw_data_fname = ranage_base+"_releaseWrite.dat";

        ofstream cmd_stream(cmd_fname.cchars());

        if(cmd_stream.bad())
          {
            cerr << "Couldn't open \"" << cmd_fname.cchars()
                 << "\" for writing"
                 << endl;
            exit(1);
          }
        
        cmd_stream << "set title \"" << title_prefix.cchars()
                   << " range " << index << "\"" << endl
                   << "set data style yerrorbars" << endl
                   << "set term png color" << endl
                   << "set output \"" << img_name.cchars() << "\"" << endl
                   << "set ylabel \"time in ms\"" << endl
                   << "set xlabel \"time 0 = " << (*it).start_time << "\""
                   << endl;

        ofstream
          *ar_data_stream = 0,
          *hr_data_stream = 0,
          *rr_data_stream = 0,
          *aw_data_stream = 0,
          *hw_data_stream = 0,
          *rw_data_stream = 0;

        unsigned int x_pos = 0;
        for(Lock_Event_List::const_iterator event_it =
              events[index].begin();
            event_it != events[index].end();
            event_it++, x_pos++)
          {
            // Open the appropriate data files if we haven't already
            if((*event_it)->write && (aw_data_stream == 0))
              {
                aw_data_stream = NEW_CONSTR(ofstream,
                                            (aw_data_fname.cchars()));
                if(aw_data_stream->bad())
                  {
                    cerr << "Couldn't open \"" << aw_data_fname.cchars()
                         << "\" for writing"
                         << endl;
                    exit(1);
                  }
                hw_data_stream = NEW_CONSTR(ofstream,
                                            (hw_data_fname.cchars()));
                if(hw_data_stream->bad())
                  {
                    cerr << "Couldn't open \"" << hw_data_fname.cchars()
                         << "\" for writing"
                         << endl;
                    exit(1);
                  }
                rw_data_stream = NEW_CONSTR(ofstream,
                                            (rw_data_fname.cchars()));
                if(rw_data_stream->bad())
                  {
                    cerr << "Couldn't open \"" << rw_data_fname.cchars()
                         << "\" for writing"
                         << endl;
                    exit(1);
                  }
              }
            else if(!(*event_it)->write && (ar_data_stream == 0))
              {
                ar_data_stream = NEW_CONSTR(ofstream,
                                            (ar_data_fname.cchars()));
                if(ar_data_stream->bad())
                  {
                    cerr << "Couldn't open \"" << ar_data_fname.cchars()
                         << "\" for writing"
                         << endl;
                    exit(1);
                  }
                hr_data_stream = NEW_CONSTR(ofstream,
                                            (hr_data_fname.cchars()));
                if(hr_data_stream->bad())
                  {
                    cerr << "Couldn't open \"" << hr_data_fname.cchars()
                         << "\" for writing"
                         << endl;
                    exit(1);
                  }
                rr_data_stream = NEW_CONSTR(ofstream,
                                            (rr_data_fname.cchars()));
                if(rr_data_stream->bad())
                  {
                    cerr << "Couldn't open \"" << rr_data_fname.cchars()
                         << "\" for writing"
                         << endl;
                    exit(1);
                  }
              }

            // Tell the event to write appropriate data lines.
            (*event_it)->plot_lock_info(x_pos,
                                        ((*event_it)->write
                                         ? *aw_data_stream
                                         : *ar_data_stream),
                                        ((*event_it)->write
                                         ? *hw_data_stream
                                         : *hr_data_stream),
                                        ((*event_it)->write
                                         ? *rw_data_stream
                                         : *rr_data_stream),
                                        (*it).start_time);
          }

        cmd_stream << "plot ";
        if(aw_data_stream != 0)
          {
            assert(hw_data_stream != 0);
            assert(rw_data_stream != 0);
            aw_data_stream->close();
            hw_data_stream->close();
            rw_data_stream->close();
            delete aw_data_stream;
            delete hw_data_stream;
            delete rw_data_stream;
            
            cmd_stream << "\"" << aw_data_fname.cchars()
                       << "\" title \"acquireWrite\", \""
                       << hw_data_fname.cchars()
                       << "\" title \"holdWrite\", \""
                       << rw_data_fname.cchars()
                       << "\" title \"releaseWrite\"";
          }
        if(ar_data_stream != 0)
          {
            assert(hr_data_stream != 0);
            assert(rr_data_stream != 0);
            ar_data_stream->close();
            hr_data_stream->close();
            rr_data_stream->close();
            delete ar_data_stream;
            delete hr_data_stream;
            delete rr_data_stream;

            if(aw_data_stream != 0)
              {
                cmd_stream << ", ";
              }
            cmd_stream << "\"" << ar_data_fname.cchars()
                       << "\" title \"acquireRead\", \""
                       << hr_data_fname.cchars()
                       << "\" title \"holdRead\", \""
                       << rr_data_fname.cchars()
                       << "\" title \"releaseRead\"";
          }
        cmd_stream << endl;
      }
  }

  bool empty()
  {
    return ranges.empty();
  }

  unsigned int range_count()
  {
    return ranges.size();
  }
};

static const char *program_name = 0;

static void usage()
{
  cerr << "Usage: " << program_name
       << " [-o <output prefix>] [-t <long acquire ms>] <lock timing file(s)>"
       << endl;
  exit(1);
}

int main(int argc, char * const argv[])
{
  program_name = argv[0];
  const char *output_prefix = "rwlock_timing.out";
  unsigned int long_acquire_ms = 1000;

  int option;
  opterr = 0;
  while((option = getopt(argc, argv, "ho:t:")) != EOF)
    {
      switch(option)
        {
        case 'o':
          output_prefix = optarg;
          break;
        case 't':
          long_acquire_ms = atoi(optarg);
          break;
        case 'h':
        case '?':
        default:
          usage();
        }
    }

  // All "long" acquire times
  Time_Ranges
    stable_long_acquireReads,
    stable_long_acquireWrites,
    volatile_long_acquireReads,
    volatile_long_acquireWrites,
    userGroup_long_acquireReads,
    userGroup_long_acquireWrites;

  // Record holders
  Lock_Data
    *stable_longest_acquireRead = 0,
    *stable_longest_acquireWrite = 0,
    *stable_longest_held = 0,
    *stable_longest_release = 0,
    *volatile_longest_acquireRead = 0,
    *volatile_longest_acquireWrite = 0,
    *volatile_longest_held = 0,
    *volatile_longest_release = 0,
    *userGroup_longest_acquireRead = 0,
    *userGroup_longest_acquireWrite = 0,
    *userGroup_longest_held = 0,
    *userGroup_longest_release = 0;

  Delta_Time
    stable_total_acquireRead,
    stable_total_acquireWrite,
    stable_total_held,
    stable_total_release,
    volatile_total_acquireRead,
    volatile_total_acquireWrite,
    volatile_total_held,
    volatile_total_release,
    userGroup_total_acquireRead,
    userGroup_total_acquireWrite,
    userGroup_total_held,
    userGroup_total_release;

  unsigned int
    stable_count_acquireRead = 0,
    stable_count_acquireWrite = 0,
    stable_count_acquired = 0,
    volatile_count_acquireRead = 0,
    volatile_count_acquireWrite = 0,
    volatile_count_acquired = 0,
    userGroup_count_acquireRead = 0,
    userGroup_count_acquireWrite = 0,
    userGroup_count_acquired = 0;

  unsigned int total_count = 0;

  unsigned int
    stable_acquireRead_no_reason_count = 0,
    stable_acquireWrite_no_reason_count = 0,
    volatile_acquireRead_no_reason_count = 0,
    volatile_acquireWrite_no_reason_count = 0,
    userGroup_acquireRead_no_reason_count = 0,
    userGroup_acquireWrite_no_reason_count = 0;

  // First pass: gather general statistics and find time periods with
  // long acquire times.

  for(int arg = optind; arg < argc; arg++)
    {
      OBufStream l_cmd;
      l_cmd << "gunzip -q -c " << argv[arg];
      FILE *stream = popen(l_cmd.str(), "r");
      unsigned long file_count = 0;

      Lock_Data *cur_stable = 0, *cur_volatile = 0, *cur_userGroup = 0;
      try
        {
          while(1)
            {
              int lock_byte = getc(stream);
              if(lock_byte == EOF)
                {
                  break;
                }
              // StableLock record
              else if(lock_byte == 1)
                {
                  if(cur_stable == 0)
                    {
                      cur_stable = NEW_CONSTR(Lock_Data, (stable));
                    }

                  bool done = cur_stable->read_record(stream);

                  if(done)
                    {
                      file_count++;

                      if(cur_stable->acquired && (cur_stable->reason == 0))
                        {
                          if(cur_stable->write)
                            {
                              stable_acquireWrite_no_reason_count++;
                            }
                          else
                            {
                              stable_acquireRead_no_reason_count++;
                            }
                        }

                      // Record "long" acquires
                      if(cur_stable->acquired &&
                         (cur_stable->time_to_acquire.msecs() >=
                          long_acquire_ms))
                        {
                          if(cur_stable->write)
                            {
                              stable_long_acquireWrites.
                                add_range(cur_stable->start_time,
                                          cur_stable->time_to_acquire);
                            }
                          else
                            {
                              stable_long_acquireReads.
                                add_range(cur_stable->start_time,
                                          cur_stable->time_to_acquire);
                            }
                        }

                      // Accumulate totals
                      if(cur_stable->write)
                        {
                          stable_total_acquireWrite +=
                            cur_stable->time_to_acquire;
                          stable_count_acquireWrite++;
                        }
                      else
                        {
                          stable_total_acquireRead +=
                            cur_stable->time_to_acquire;
                          stable_count_acquireRead++;
                        }
                      if(cur_stable->acquired)
                        {
                          stable_total_held += cur_stable->time_held;
                          stable_total_release += cur_stable->time_to_release;
                          stable_count_acquired++;
                        }

                      // Store record holders
                      if(cur_stable->write &&
                         (!stable_longest_acquireWrite ||
                          (cur_stable->time_to_acquire >
                           stable_longest_acquireWrite->time_to_acquire)))
                        {
                          stable_longest_acquireWrite = cur_stable;
                        }
                      if(!cur_stable->write &&
                         (!stable_longest_acquireRead ||
                          (cur_stable->time_to_acquire >
                           stable_longest_acquireRead->time_to_acquire)))
                        {
                          stable_longest_acquireRead = cur_stable;
                        }
                      if(cur_stable->acquired)
                        {
                          if(!stable_longest_held ||
                             (cur_stable->time_held >
                              stable_longest_held->time_held))
                            {
                              stable_longest_held = cur_stable;
                            }
                          if(!stable_longest_release ||
                             (cur_stable->time_to_release >
                              stable_longest_release->time_to_release))
                            {
                              stable_longest_release = cur_stable;
                            }
                        }
                         
                      cur_stable = 0;
                    }
                }
              // VolatileRootLock record
              else if(lock_byte == 2)
                {
                  if(cur_volatile == 0)
                    {
                      cur_volatile = NEW_CONSTR(Lock_Data, (volatileRoot));
                    }

                  bool done = cur_volatile->read_record(stream);

                  if(done)
                    {
                      file_count++;

                      if(cur_volatile->acquired && (cur_volatile->reason == 0))
                        {
                          if(cur_volatile->write)
                            {
                              volatile_acquireWrite_no_reason_count++;
                            }
                          else
                            {
                              volatile_acquireRead_no_reason_count++;
                            }
                        }

                      // Record "long" acquires
                      if(cur_volatile->acquired &&
                         (cur_volatile->time_to_acquire.msecs() >=
                          long_acquire_ms))
                        {
                          if(cur_volatile->write)
                            {
                              volatile_long_acquireWrites.
                                add_range(cur_volatile->start_time,
                                          cur_volatile->time_to_acquire);
                            }
                          else
                            {
                              volatile_long_acquireReads.
                                add_range(cur_volatile->start_time,
                                          cur_volatile->time_to_acquire);
                            }
                        }

                      // Accumulate totals
                      if(cur_volatile->write)
                        {
                          volatile_total_acquireWrite +=
                            cur_volatile->time_to_acquire;
                          volatile_count_acquireWrite++;
                        }
                      else
                        {
                          volatile_total_acquireRead +=
                            cur_volatile->time_to_acquire;
                          volatile_count_acquireRead++;
                        }
                      if(cur_volatile->acquired)
                        {
                          volatile_total_held += cur_volatile->time_held;
                          volatile_total_release +=
                            cur_volatile->time_to_release;
                          volatile_count_acquired++;
                        }

                      // Store record holders
                      if(cur_volatile->write &&
                         (!volatile_longest_acquireWrite ||
                          (cur_volatile->time_to_acquire >
                           volatile_longest_acquireWrite->time_to_acquire)))
                        {
                          volatile_longest_acquireWrite = cur_volatile;
                        }
                      if(!cur_volatile->write &&
                         (!volatile_longest_acquireRead ||
                          (cur_volatile->time_to_acquire >
                           volatile_longest_acquireRead->time_to_acquire)))
                        {
                          volatile_longest_acquireRead = cur_volatile;
                        }
                      if(cur_volatile->acquired)
                        {
                          if(!volatile_longest_held ||
                             (cur_volatile->time_held >
                              volatile_longest_held->time_held))
                            {
                              volatile_longest_held = cur_volatile;
                            }
                          if(!volatile_longest_release ||
                             (cur_volatile->time_to_release >
                              volatile_longest_release->time_to_release))
                            {
                              volatile_longest_release = cur_volatile;
                            }
                        }

                      cur_volatile = 0;
                    }
                }
              // userGroup_lock record
              else if(lock_byte == 3)
                {
                  if(cur_userGroup == 0)
                    {
                      cur_userGroup = NEW_CONSTR(Lock_Data, (userGroup));
                    }

                  bool done = cur_userGroup->read_record(stream);

                  if(done)
                    {
                      file_count++;

                      if(cur_userGroup->acquired && (cur_userGroup->reason == 0))
                        {
                          if(cur_userGroup->write)
                            {
                              userGroup_acquireWrite_no_reason_count++;
                            }
                          else
                            {
                              userGroup_acquireRead_no_reason_count++;
                            }
                        }

                      // Record "long" acquires
                      if(cur_userGroup->acquired &&
                         (cur_userGroup->time_to_acquire.msecs() >=
                          long_acquire_ms))
                        {
                          if(cur_userGroup->write)
                            {
                              userGroup_long_acquireWrites.
                                add_range(cur_userGroup->start_time,
                                          cur_userGroup->time_to_acquire);
                            }
                          else
                            {
                              userGroup_long_acquireReads.
                                add_range(cur_userGroup->start_time,
                                          cur_userGroup->time_to_acquire);
                            }
                        }

                      // Accumulate totals
                      if(cur_userGroup->write)
                        {
                          userGroup_total_acquireWrite +=
                            cur_userGroup->time_to_acquire;
                          userGroup_count_acquireWrite++;
                        }
                      else
                        {
                          userGroup_total_acquireRead +=
                            cur_userGroup->time_to_acquire;
                          userGroup_count_acquireRead++;
                        }
                      if(cur_userGroup->acquired)
                        {
                          userGroup_total_held += cur_userGroup->time_held;
                          userGroup_total_release +=
                            cur_userGroup->time_to_release;
                          userGroup_count_acquired++;
                        }

                      // Store record holders
                      if(cur_userGroup->write &&
                         (!userGroup_longest_acquireWrite ||
                          (cur_userGroup->time_to_acquire >
                           userGroup_longest_acquireWrite->time_to_acquire)))
                        {
                          userGroup_longest_acquireWrite = cur_userGroup;
                        }
                      if(!cur_userGroup->write &&
                         (!userGroup_longest_acquireRead ||
                          (cur_userGroup->time_to_acquire >
                           userGroup_longest_acquireRead->time_to_acquire)))
                        {
                          userGroup_longest_acquireRead = cur_userGroup;
                        }
                      if(cur_userGroup->acquired)
                        {
                          if(!userGroup_longest_held ||
                             (cur_userGroup->time_held >
                              userGroup_longest_held->time_held))
                            {
                              userGroup_longest_held = cur_userGroup;
                            }
                          if(!userGroup_longest_release ||
                             (cur_userGroup->time_to_release >
                              userGroup_longest_release->time_to_release))
                            {
                              userGroup_longest_release = cur_userGroup;
                            }
                        }

                      cur_userGroup = 0;
                    }
                }
            }
        }
      catch(FS::EndOfFile)
        {
          // We don't care
        }
      catch(Lock_Data::FileFormatError)
        {
          cerr << "File format error reading " << argv[arg] << endl;
        }

      cout << argv[arg] << ": " << file_count << " locks" << endl;
      total_count +=  file_count;
      int gunzip_status = pclose(stream);
      cout << "gunzip status: " << gunzip_status << endl;
    }

  Text report_fname(output_prefix);
  report_fname += ".report";
  ofstream report(report_fname.cchars());

  if(report.bad())
    {
      cerr << "Couldn't open \"" << report_fname.cchars() << "\" for writing"
           << endl;
      exit(1);
    }

  report << "Total: " << total_count << " locks" << endl;

  report << "Acquired locks with no reason:" << endl
         << "  StableLock acquireRead:        "
         << stable_acquireRead_no_reason_count << endl
         << "  StableLock acquireWrite:       "
         << stable_acquireWrite_no_reason_count << endl
         << "  VolatileRootLock acquireRead:  "
         << volatile_acquireRead_no_reason_count << endl
         << "  VolatileRootLock acquireWrite: "
         << volatile_acquireWrite_no_reason_count << endl
         << "  userGroup_lock acquireRead:  "
         << userGroup_acquireRead_no_reason_count << endl
         << "  userGroup_lock acquireWrite: "
         << userGroup_acquireWrite_no_reason_count << endl;

  report << "StableLock:" << endl;
  if(stable_count_acquireRead > 0)
    {
      assert(stable_longest_acquireRead != 0);
      report
        << "  acquireRead/tryRead:" << endl
        << "    average: " << (stable_total_acquireRead.msecs() /
                               stable_count_acquireRead) << " ms" << endl
        << "    slowest: "
        << stable_longest_acquireRead->time_to_acquire.msecs()
        << " ms" << endl;
      if(stable_longest_acquireRead->reason)
        {
          report
            << "    slowest reason: "
            << stable_longest_acquireRead->reason->cchars() << endl;
        }
      if(!stable_long_acquireReads.empty())
        {
          report << "    long acquireRead periods:" << endl;
          stable_long_acquireReads.print(report, "      ");
        }
    }
  if(stable_count_acquireWrite > 0)
    {
      assert(stable_longest_acquireWrite != 0);
      report
        << "  acquireWrite/tryWrite:" << endl
        << "    average: " << (stable_total_acquireWrite.msecs() /
                               stable_count_acquireWrite) << " ms" << endl
        << "    slowest: "
        << stable_longest_acquireWrite->time_to_acquire.msecs()
        << " ms" << endl;
      if(stable_longest_acquireWrite->reason)
        {
          report
            << "    slowest reason: "
            << stable_longest_acquireWrite->reason->cchars() << endl;
        }
      if(!stable_long_acquireWrites.empty())
        {
          report << "    long acquireWrite periods:" << endl;
          stable_long_acquireWrites.print(report, "      ");
        }
    }
  if(stable_count_acquired > 0)
    {
      assert(stable_longest_held != 0);
      assert(stable_longest_release != 0);
      report
        << "  hold:" << endl
        << "    average: " << (stable_total_held.msecs() /
                               stable_count_acquired) << " ms" << endl
        << "    slowest: " << stable_longest_held->time_held.msecs()
        << " ms" << endl;
      if(stable_longest_held->reason)
        {
          report
            << "    slowest reason: "
            << stable_longest_held->reason->cchars() << endl;
        }
      report
        << "  release:" << endl
        << "    average: " << (stable_total_release.msecs() /
                               stable_count_acquired) << " ms" << endl
        << "    slowest: " << stable_longest_release->time_to_release.msecs()
        << " ms" << endl;
      if(stable_longest_release->reason)
        {
          report
            << "    slowest reason: "
            << stable_longest_release->reason->cchars() << endl;
        }
    }
  report << "VolatileRootLock:" << endl;
  if(volatile_count_acquireRead > 0)
    {
      assert(volatile_longest_acquireRead != 0);
      report
        << "  acquireRead/tryRead:" << endl
        << "    average: " << (volatile_total_acquireRead.msecs() /
                               volatile_count_acquireRead) << " ms" << endl
        << "    slowest: "
        << volatile_longest_acquireRead->time_to_acquire.msecs()
        << " ms" << endl;
      if(volatile_longest_acquireRead->reason)
        {
          report
            << "    slowest reason: "
            << volatile_longest_acquireRead->reason->cchars() << endl;
        }
      if(!volatile_long_acquireReads.empty())
        {
          report << "    long acquireRead periods:" << endl;
          volatile_long_acquireReads.print(report, "      ");
        }
    }
  if(volatile_count_acquireWrite > 0)
    {
      assert(volatile_longest_acquireWrite != 0);
      report
        << "  acquireWrite/tryWrite:" << endl
        << "    average: " << (volatile_total_acquireWrite.msecs() /
                               volatile_count_acquireWrite) << " ms" << endl
        << "    slowest: "
        << volatile_longest_acquireWrite->time_to_acquire.msecs()
        << " ms" << endl;
      if(volatile_longest_acquireWrite->reason)
        {
          report
            << "    slowest reason: "
            << volatile_longest_acquireWrite->reason->cchars() << endl;
        }
      if(!volatile_long_acquireWrites.empty())
        {
          report << "    long acquireWrite periods:" << endl;
          volatile_long_acquireWrites.print(report, "      ");
        }
    }
  if(volatile_count_acquired > 0)
    {
      assert(volatile_longest_held != 0);
      assert(volatile_longest_release != 0);
      report
        << "  hold:" << endl
        << "    average: " << (volatile_total_held.msecs() /
                               volatile_count_acquired) << " ms" << endl
        << "    slowest: " << volatile_longest_held->time_held.msecs()
        << " ms" << endl;
      if(volatile_longest_held->reason)
        {
          report
            << "    slowest reason: "
            << volatile_longest_held->reason->cchars() << endl;
        }
      report
        << "  release:" << endl
        << "    average: " << (volatile_total_release.msecs() /
                               volatile_count_acquired) << " ms" << endl
        << "    slowest: " << volatile_longest_release->time_to_release.msecs()
        << " ms" << endl;
      if(volatile_longest_release->reason)
        {
          report
            << "    slowest reason: "
            << volatile_longest_release->reason->cchars() << endl;
        }
    }
  report << "userGroup_lock [AccessControl.C]:" << endl;
  if(userGroup_count_acquireRead > 0)
    {
      assert(userGroup_longest_acquireRead != 0);
      report
        << "  acquireRead/tryRead:" << endl
        << "    average: " << (userGroup_total_acquireRead.msecs() /
                               userGroup_count_acquireRead) << " ms" << endl
        << "    slowest: "
        << userGroup_longest_acquireRead->time_to_acquire.msecs()
        << " ms" << endl;
      if(userGroup_longest_acquireRead->reason)
        {
          report
            << "    slowest reason: "
            << userGroup_longest_acquireRead->reason->cchars() << endl;
        }
      if(!userGroup_long_acquireReads.empty())
        {
          report << "    long acquireRead periods:" << endl;
          userGroup_long_acquireReads.print(report, "      ");
        }
    }
  if(userGroup_count_acquireWrite > 0)
    {
      assert(userGroup_longest_acquireWrite != 0);
      report
        << "  acquireWrite/tryWrite:" << endl
        << "    average: " << (userGroup_total_acquireWrite.msecs() /
                               userGroup_count_acquireWrite) << " ms" << endl
        << "    slowest: "
        << userGroup_longest_acquireWrite->time_to_acquire.msecs()
        << " ms" << endl;
      if(userGroup_longest_acquireWrite->reason)
        {
          report
            << "    slowest reason: "
            << userGroup_longest_acquireWrite->reason->cchars() << endl;
        }
      if(!userGroup_long_acquireWrites.empty())
        {
          report << "    long acquireWrite periods:" << endl;
          userGroup_long_acquireWrites.print(report, "      ");
        }
    }
  if(userGroup_count_acquired > 0)
    {
      assert(userGroup_longest_held != 0);
      assert(userGroup_longest_release != 0);
      report
        << "  hold:" << endl
        << "    average: " << (userGroup_total_held.msecs() /
                               userGroup_count_acquired) << " ms" << endl
        << "    slowest: " << userGroup_longest_held->time_held.msecs()
        << " ms" << endl;
      if(userGroup_longest_held->reason)
        {
          report
            << "    slowest reason: "
            << userGroup_longest_held->reason->cchars() << endl;
        }
      report
        << "  release:" << endl
        << "    average: " << (userGroup_total_release.msecs() /
                               userGroup_count_acquired) << " ms" << endl
        << "    slowest: " << userGroup_longest_release->time_to_release.msecs()
        << " ms" << endl;
      if(userGroup_longest_release->reason)
        {
          report
            << "    slowest reason: "
            << userGroup_longest_release->reason->cchars() << endl;
        }
    }

  // Second pass: find all lock events that overlap with periods of
  // long acquire times.

  Lock_Event_List
    *stable_long_acquireRead_events = 0,
    *stable_long_acquireWrite_events = 0,
    *volatile_long_acquireRead_events = 0,
    *volatile_long_acquireWrite_events = 0,
    *userGroup_long_acquireRead_events = 0,
    *userGroup_long_acquireWrite_events = 0;

  if(!stable_long_acquireReads.empty())
    {
      stable_long_acquireRead_events =
        NEW_ARRAY(Lock_Event_List, stable_long_acquireReads.range_count());
    }
  if(!stable_long_acquireWrites.empty())
    {
      stable_long_acquireWrite_events =
        NEW_ARRAY(Lock_Event_List, stable_long_acquireWrites.range_count());
    }
  if(!volatile_long_acquireReads.empty())
    {
      volatile_long_acquireRead_events =
        NEW_ARRAY(Lock_Event_List, volatile_long_acquireReads.range_count());
    }
  if(!volatile_long_acquireWrites.empty())
    {
      volatile_long_acquireWrite_events =
        NEW_ARRAY(Lock_Event_List, volatile_long_acquireWrites.range_count());
    }
  if(!userGroup_long_acquireReads.empty())
    {
      userGroup_long_acquireRead_events =
        NEW_ARRAY(Lock_Event_List, userGroup_long_acquireReads.range_count());
    }
  if(!userGroup_long_acquireWrites.empty())
    {
      userGroup_long_acquireWrite_events =
        NEW_ARRAY(Lock_Event_List, userGroup_long_acquireWrites.range_count());
    }

  if((stable_long_acquireRead_events == 0) &&
     (stable_long_acquireWrite_events == 0) &&
     (volatile_long_acquireRead_events == 0) &&
     (volatile_long_acquireWrite_events == 0) &&
     (userGroup_long_acquireRead_events == 0) &&
     (userGroup_long_acquireWrite_events == 0))
    {
      cout << "No long acquire periods: skipping second pass" << endl;
      return 0;
    }

  cout << "Starting second pass..." << endl;
  for(int arg = optind; arg < argc; arg++)
    {
      OBufStream l_cmd;
      l_cmd << "gunzip -q -c " << argv[arg];
      FILE *stream = popen(l_cmd.str(), "r");

      Lock_Data *cur_stable = 0, *cur_volatile = 0, *cur_userGroup = 0;
      try
        {
          while(1)
            {
              int lock_byte = getc(stream);
              if(lock_byte == EOF)
                {
                  break;
                }
              // StableLock record
              else if(lock_byte == 1)
                {
                  if(cur_stable == 0)
                    {
                      cur_stable = NEW_CONSTR(Lock_Data, (stable));
                    }

                  bool done = cur_stable->read_record(stream);

                  if(done)
                    {
                      Delta_Time total_delta;
                      if(cur_stable->acquired)
                        {
                          total_delta = (cur_stable->time_to_acquire +
                                         cur_stable->time_held +
                                         cur_stable->time_to_release);
                        }
                      else
                        {
                          total_delta = cur_stable->time_to_acquire;
                        }

                      unsigned int index = 0;
                      while(stable_long_acquireReads
                            .in_range(cur_stable->start_time, total_delta,
                                      index))
                        {
                          assert(stable_long_acquireRead_events != 0);
                          sorted_lock_insert
                            (stable_long_acquireRead_events[index],
                             cur_stable);
                          // Search next from the subsequent index.
                          index++;
                        }
                      index = 0;
                      while(stable_long_acquireWrites
                         .in_range(cur_stable->start_time, total_delta,
                                   index))
                        {
                          assert(stable_long_acquireWrite_events != 0);
                          sorted_lock_insert
                            (stable_long_acquireWrite_events[index],
                             cur_stable);
                          // Search next from the subsequent index.
                          index++;
                        }

                      cur_stable = 0;
                    }
                }
              // VolatileRootLock record
              else if(lock_byte == 2)
                {
                  if(cur_volatile == 0)
                    {
                      cur_volatile = NEW_CONSTR(Lock_Data, (volatileRoot));
                    }

                  bool done = cur_volatile->read_record(stream);

                  if(done)
                    {
                      Delta_Time total_delta;
                      if(cur_volatile->acquired)
                        {
                          total_delta = (cur_volatile->time_to_acquire +
                                         cur_volatile->time_held +
                                         cur_volatile->time_to_release);
                        }
                      else
                        {
                          total_delta = cur_volatile->time_to_acquire;
                        }

                      unsigned int index = 0;
                      while(volatile_long_acquireReads
                         .in_range(cur_volatile->start_time, total_delta,
                                   index))
                        {
                          assert(volatile_long_acquireRead_events != 0);
                          sorted_lock_insert
                            (volatile_long_acquireRead_events[index],
                             cur_volatile);
                          // Search next from the subsequent index.
                          index++;
                        }
                      index = 0;
                      while(volatile_long_acquireWrites
                         .in_range(cur_volatile->start_time, total_delta,
                                   index))
                        {
                          assert(volatile_long_acquireWrite_events != 0);
                          sorted_lock_insert
                            (volatile_long_acquireWrite_events[index],
                             cur_volatile);
                          // Search next from the subsequent index.
                          index++;
                        }

                      cur_volatile = 0;
                    }
                }
              // userGroup_lock record
              else if(lock_byte == 3)
                {
                  if(cur_userGroup == 0)
                    {
                      cur_userGroup = NEW_CONSTR(Lock_Data, (userGroup));
                    }

                  bool done = cur_userGroup->read_record(stream);

                  if(done)
                    {
                      Delta_Time total_delta;
                      if(cur_userGroup->acquired)
                        {
                          total_delta = (cur_userGroup->time_to_acquire +
                                         cur_userGroup->time_held +
                                         cur_userGroup->time_to_release);
                        }
                      else
                        {
                          total_delta = cur_userGroup->time_to_acquire;
                        }

                      unsigned int index = 0;
                      while(userGroup_long_acquireReads
                         .in_range(cur_userGroup->start_time, total_delta,
                                   index))
                        {
                          assert(userGroup_long_acquireRead_events != 0);
                          sorted_lock_insert
                            (userGroup_long_acquireRead_events[index],
                             cur_userGroup);
                          // Search next from the subsequent index.
                          index++;
                        }
                      index = 0;
                      while(userGroup_long_acquireWrites
                         .in_range(cur_userGroup->start_time, total_delta,
                                   index))
                        {
                          assert(userGroup_long_acquireWrite_events != 0);
                          sorted_lock_insert
                            (userGroup_long_acquireWrite_events[index],
                             cur_userGroup);
                          // Search next from the subsequent index.
                          index++;
                        }

                      cur_userGroup = 0;
                    }
                }
            }
        }
      catch(FS::EndOfFile)
        {
          // We don't care
        }
      catch(Lock_Data::FileFormatError)
        {
          cerr << "File format error reading " << argv[arg] << endl;
        }

      int gunzip_status = pclose(stream);
    }

  // Print events for periods with long acquire waits.

  if(!stable_long_acquireReads.empty())
    {
      assert(stable_long_acquireRead_events != 0);
      report << "Long StableLock acquireRead periods:" << endl;
      stable_long_acquireReads.print(report, "  ",
                                     stable_long_acquireRead_events);

      Text plot_prefix(output_prefix);
      plot_prefix += ".long_StableLock_acquireRead";
      stable_long_acquireReads
        .gen_plot("Long StableLock acquireRead",
                  plot_prefix,
                  stable_long_acquireRead_events);
    }
  if(!stable_long_acquireWrites.empty())
    {
      assert(stable_long_acquireWrite_events != 0);
      report << "Long StableLock acquireWrite periods:" << endl;
      stable_long_acquireWrites.print(report, "  ",
                                      stable_long_acquireWrite_events);

      Text plot_prefix(output_prefix);
      plot_prefix += ".long_StableLock_acquireWrite";
      stable_long_acquireWrites
        .gen_plot("Long StableLock acquireWrite",
                  plot_prefix,
                  stable_long_acquireWrite_events);
    }
  if(!volatile_long_acquireReads.empty())
    {
      assert(volatile_long_acquireRead_events != 0);
      report << "Long VolatileRootLock acquireRead periods:" << endl;
      volatile_long_acquireReads.print(report, "  ",
                                       volatile_long_acquireRead_events);

      Text plot_prefix(output_prefix);
      plot_prefix += ".long_VolatileRootLock_acquireRead";
      volatile_long_acquireReads
        .gen_plot("Long VolatileRootLock acquireRead",
                  plot_prefix,
                  volatile_long_acquireRead_events);
    }
  if(!volatile_long_acquireWrites.empty())
    {
      assert(volatile_long_acquireWrite_events != 0);
      report << "Long VolatileRootLock acquireWrite periods:" << endl;
      volatile_long_acquireWrites.print(report, "  ",
                                        volatile_long_acquireWrite_events);

      Text plot_prefix(output_prefix);
      plot_prefix += ".long_VolatileRootLock_acquireWrite";
      volatile_long_acquireWrites
        .gen_plot("Long VolatileRootLock acquireWrite",
                  plot_prefix,
                  volatile_long_acquireWrite_events);
    }
  if(!userGroup_long_acquireReads.empty())
    {
      assert(userGroup_long_acquireRead_events != 0);
      report << "Long userGroup_lock acquireRead periods:" << endl;
      userGroup_long_acquireReads.print(report, "  ",
                                       userGroup_long_acquireRead_events);

      Text plot_prefix(output_prefix);
      plot_prefix += ".long_userGroup_acquireRead";
      userGroup_long_acquireReads
        .gen_plot("Long userGroup_lock acquireRead",
                  plot_prefix,
                  userGroup_long_acquireRead_events);
    }
  if(!userGroup_long_acquireWrites.empty())
    {
      assert(userGroup_long_acquireWrite_events != 0);
      report << "Long userGroup_lock acquireWrite periods:" << endl;
      userGroup_long_acquireWrites.print(report, "  ",
                                        userGroup_long_acquireWrite_events);

      Text plot_prefix(output_prefix);
      plot_prefix += ".long_userGroup_acquireWrite";
      userGroup_long_acquireWrites
        .gen_plot("Long userGroup_lock acquireWrite",
                  plot_prefix,
                  userGroup_long_acquireWrite_events);
    }

  return 0;
}

---