read_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_timing.C - Tool for reading and analyzing the repository's
// fine-grained NFS call timing.

// Last modified on Fri Apr 22 13:42:05 EDT 2005 by ken@xorian.net

#include <sys/time.h> /* struct timeval */
#include <Basics.H>
#include <BasicsAllocator.H>
#include <BufStream.H>
#include <Generics.H>
#include <FS.H>

#include <list>
#include <algorithm>

#include <stdio.h>
#include <math.h>
#include <getopt.h>

#include "nfs_prot.h"

#include <ReposUI.H>

#include "read_timing_common.H"

#include <iomanip>

using std::ostream;
using std::ofstream;
using std::cout;
using std::cerr;
using std::endl;
using std::setw;
using std::setfill;
using std::hex;
using std::dec;
using std::list;
using std::sort;
using std::lower_bound;
using Basics::OBufStream;

static int IntCompare(const void *v1, const void *v2) throw ()
{
    unsigned int *i1 = (unsigned int *)v1, *i2 = (unsigned int *)v2;
    return *i1 - *i2;
}

class Histogram
{
public:
  typedef unsigned int (*histo_map_t)(unsigned int);
private:
  histo_map_t histo_map;
  IntIntTbl tbl;

public:
  Histogram(histo_map_t map_func)
    : histo_map(map_func)
  {
  }
  Histogram()
    : histo_map(0)
  {
  }

  void SetHistoMap(histo_map_t map_func)
  {
    assert(this->histo_map == 0);
    this->histo_map = map_func;
  }

  void AddVal(unsigned int val)
  {
    if(this->histo_map)
      val = (*(this->histo_map))(val);
    IntKey key(val);
    int cnt = 0;
    (void) this->tbl.Get(key, /*OUT*/ cnt);
    cnt++;
    (void) this->tbl.Put(key, cnt);
  }

  void PrintHisto(ostream &out) const throw ()
  {
    // iterate over table to find the largest key
    IntIntIter it(&(this->tbl));
    IntKey key; int val, i = 0;
    int max_key = 0;
    while (it.Next(/*OUT*/ key, /*OUT*/ val))
      {
        if(key.Val() > max_key)
          {
            max_key = key.Val();
          }
      }

    // Print the histogram in increasing key order.  Note that we may
    // print lines for values not in the table.  This makes for data
    // more readily usable with gnuplot.
    for (i = 0; i <= max_key; i++)
      {
        key = i;
        val = 0;
        (void) this->tbl.Get(key, /*OUT*/ val);
        out << i << "\t" << val << endl;
      }
  }

  Histogram &operator+=(const Histogram &other)
  {
    // We'd better both be using the same histogram mapping function.
    assert(other.histo_map == this->histo_map);

    // iterate over table, filling keys array
    IntIntIter it(&(other.tbl));
    IntKey key; int val;
    while (it.Next(/*OUT*/ key, /*OUT*/ val))
      {
        int my_count = 0;
        (void) this->tbl.Get(key, /*OUT*/ my_count);
        my_count += val;
        (void) this->tbl.Put(key, my_count);
      }

    return *this;
  }
};

// For use with Histogram

static unsigned int Log2(unsigned int x) throw ()
{
    int res = 0;
    for (unsigned int n = 1U; n < x; n <<= 1) res++;
    return res;
}

struct Time_Point
{
  Atom file;
  unsigned short line;

  Delta_Time delta;

  void read(FILE *input) throw(FS::EndOfFile)
  {
    // Read the delta time
    delta.read(input);

    // Read the filename
    char fname_buf[1024];
    unsigned int fname_pos = 0;
    int next_char;
    while((next_char = getc(input)) != EOF)
      {
        fname_buf[fname_pos++] = next_char;
        if(next_char == 0)
          break;
      }
    if(next_char == EOF)
      {
        throw FS::EndOfFile();
      }
    file = fname_buf;

    // Read the line number
    size_t n_read = fread((void *) &line, sizeof(line), 1, input);
    if(n_read < 1)
      {
        throw FS::EndOfFile();
      }
    assert(n_read == 1);
  }

  Time_Point(FILE *input) throw(FS::EndOfFile)
  {
    read(input);
  }

  Time_Point()
    : line(0), file("<invalid>")
  {
  }

  Time_Point(const Time_Point &other)
    : file(other.file), line(other.line), delta(other.delta)
  {
  }

  bool operator==(const Time_Point &other) const throw()
  {
    return ((file == other.file) &&
            (line == other.line) &&
            (delta == other.delta));
  }

  Time_Point &operator=(const Time_Point &other) throw()
  {
    file = other.file;
    line = other.line;
    delta = other.delta;
    return *this;
  }

  bool operator!=(const Time_Point &other) const throw()
  {
    return !(*this == other);
  }

  Text as_text() const throw()
  {
    OBufStream time_point_stream;
    time_point_stream << this->file << ":"
                      << this->line;
    return Text(time_point_stream.str());
  }
};

typedef Sequence<Time_Point> Time_Point_Seq;

struct Source_Interval
{
  Atom start, end;

  Source_Interval()
    : start("<invalid strart>"), end("<invalid end>")
  {
  }

  Source_Interval(const Source_Interval &other)
    : start(other.start), end(other.end)
  {
  }

  Source_Interval(const Atom &start, const Atom &end)
    : start(start), end(end)
  {
  }

  // Methods required to be a key in a Table

  Word Hash() const throw ()
  {
    return (start.Hash() ^ end.Hash());
  }

  Source_Interval& operator=(const Source_Interval &other) throw ()
  {
    start = other.start;
    end = other.end;
    return *this;
  }

  bool operator == (const Source_Interval &other) throw ()
  {
    return ((start == other.start) && (end == other.end));
  }

  Text as_fname() const throw()
  {
    return Text(start.cchars())+"_to_"+end;
  }

  Text as_text() const throw()
  {
    return Text(start.cchars())+" to "+end;
  }
};

ostream &operator<<(ostream &out, const Source_Interval &interval)
{
  out << interval.as_text();
  return out;
}

// The represents the time interval in which a LongId was recorded.
// (The intent is that this time interval is the one where it's worth
// knowing the LongId.)
struct LongId_Point
{
  LongId *longid;
  Delta_Time time;

  LongId_Point(LongId *l, Delta_Time t) : longid(l), time(t) { }
  LongId_Point(const LongId_Point &other) : longid(other.longid), time(other.time) { }
  LongId_Point() : longid(0) { }

  LongId_Point &operator=(const LongId_Point &other)
  {
    longid = other.longid;
    time = other.time;
    return *this;
  }

  // Compare based on delta time.
  bool operator<(const LongId_Point &other) const
  {
    return other.time > this->time;
  }
};

bool LongId_Point_Slower(const LongId_Point &a, const LongId_Point &b)
{
  return a.time > b.time;
}

typedef list<LongId_Point,
             Basics::Allocator<LongId_Point> > LongId_Point_List;

typedef Table<Source_Interval, Delta_Time>::Default Interval_Times;
typedef Table<Source_Interval, Delta_Time>::Iterator Interval_Times_Iter;

typedef Table<Source_Interval, unsigned long>::Default Interval_Counts;
typedef Table<Source_Interval, unsigned long>::Iterator Interval_Counts_Iter;

typedef Table<Source_Interval, Histogram*>::Default Interval_Histos;
typedef Table<Source_Interval, Histogram*>::Iterator Interval_Histos_Iter;

typedef Table<Source_Interval, LongId_Point_List*>::Default LongId_Intervals;
typedef Table<Source_Interval, LongId_Point_List*>::Iterator LongId_Intervals_Iter;

class Interval_Time_Greater
{
private:
  Interval_Times &table;
public:
  Interval_Time_Greater(Interval_Times &table)
    : table(table)
  {
  }

  bool operator()(const Source_Interval &a, const Source_Interval &b)
  {
    Delta_Time time_a, time_b;
    bool inTbl = table.Get(a, time_a);
    assert(inTbl);
    inTbl = table.Get(b, time_b);
    assert(inTbl);

    return time_a > time_b;
  }
};

class Interval_Count_Greater
{
private:
  Interval_Counts &table;
public:
  Interval_Count_Greater(Interval_Counts &table)
    : table(table)
  {
  }

  bool operator()(const Source_Interval &a, const Source_Interval &b)
  {
    unsigned long count_a, count_b;
    bool inTbl = table.Get(a, count_a);
    assert(inTbl);
    inTbl = table.Get(b, count_b);
    assert(inTbl);

    return count_a > count_b;
  }
};

Interval_Times &operator+=(Interval_Times &lhs, const Interval_Times &rhs)
{
  Interval_Times_Iter rhs_iter(&rhs);
  Source_Interval interval;
  Delta_Time rhs_time;
  while(rhs_iter.Next(interval, rhs_time))
    {
      Delta_Time lhs_time;
      (void) lhs.Get(interval, lhs_time);
      lhs_time += rhs_time;
      (void) lhs.Put(interval, lhs_time);
    }

  return lhs;
}

template<class K, class V>
K *table_keys(const typename Table<K, V>::Default &table)
{
  unsigned int size = table.Size(), i = 0;
  K *result = NEW_ARRAY(K, table.Size());

  typename Table<K, V>::Iterator iter(&table);
  V unused;
  while(iter.Next(result[i], unused))
    {
      i++;
      assert(i <= size);
    }
  assert(i == size);

  return result;
}

struct Call_Data
{
  struct FileFormatError {};
  struct timeval start_time;
  Delta_Time elapsed_time;

  int proc;

  Time_Point_Seq time_points;

  bool duplicate, have_dupe;
  Delta_Time dupe_time;

  LongId *longid;
  unsigned int longid_start_point;

  void read(FILE *input) throw(FS::EndOfFile, FileFormatError)
  {
    int next_byte = getc(input);
    if(next_byte == 1)
      {
        // NFS procedure of this call
        proc = getc(input);
        if(proc == EOF)
          {
            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;
        while(1)
          {
            next_byte = getc(input);
            if(next_byte == EOF)
              {
                throw FS::EndOfFile();
              }
            // Intermediate time point
            else if(next_byte == 2)
              {
                Time_Point point(input);

                time_points.addhi(point);
              }
            // End of call
            else if(next_byte == 3)
              {
                elapsed_time.read(input);
                break;
              }
            // Duplicate status
            else if((next_byte == 4) || (next_byte == 5))
              {
                duplicate = (next_byte == 5);
                dupe_time.read(input);
                have_dupe = true;
              }
            // LongId
            else if(next_byte == 6)
              {
                longid = NEW(LongId);
                longid_start_point = time_points.size();
                size_t read_count = fread(&(longid->value.byte[0]),
                                          sizeof(longid->value), 1,
                                          input);
                if(read_count < 1)
                  {
                    throw FS::EndOfFile();
                  }
              }
          }
      }
    else if(next_byte == EOF)
      {
        throw FS::EndOfFile();
      }
    else
      {
        // File format error?
        throw FileFormatError();
      }
  }

  Call_Data(FILE *input) throw(FS::EndOfFile, FileFormatError)
    : have_dupe(false), longid(0)
  {
    read(input);
  }

  Call_Data() throw()
    : have_dupe(false), proc(NFSPROC_NULL), longid(0)
  {
  }

  Interval_Times *compute_interval_times(Source_Interval &max_interval,
                                         Source_Interval &longid_interval);

  void longid_interval(Source_Interval &interval,
                       Delta_Time &time) const;

  // Required to be in a list

  bool operator==(const Call_Data &other) const
  {
    // Simple comparisons first
    if((this->proc != other.proc) ||
       (this->start_time.tv_sec != other.start_time.tv_sec) ||
       (this->start_time.tv_usec != other.start_time.tv_usec) ||
       (this->elapsed_time != other.elapsed_time) ||
       (this->time_points.size() != other.time_points.size()))
      return false;

    // Duplicate status/time comparison
    if(this->have_dupe)
      {
        if(!other.have_dupe)
          return false;

        if((this->duplicate && !other.duplicate) ||
           (!this->duplicate && other.duplicate))
          return false;

        if(this->dupe_time != other.dupe_time)
          return false;
      }

    // Time point comparison
    for(unsigned int i = 0; i < this->time_points.size(); i++)
      {
        if(this->time_points.get(i) != other.time_points.get(i))
          return false;
      }

    // I guess they're equal.
    return true;
  }

  // Compare based on elapsed time.
  bool operator<(const Call_Data &other) const
  {
    return other.elapsed_time > this->elapsed_time;
  }
};

Interval_Times *Call_Data::compute_interval_times(Source_Interval &max_interval,
                                                  Source_Interval &longid_interval)
{
  Interval_Times *result = NEW_CONSTR(Interval_Times,
                                      (time_points.size(), true));
  Delta_Time last_time;
  Atom last_point = "start";
  Delta_Time max_time;

  if(have_dupe)
    {
      Atom current_point = "dupe";
      Source_Interval interval(last_point, current_point);
      (void) result->Put(interval, dupe_time);

      last_time = dupe_time;
      last_point = current_point;

      max_time = dupe_time;
      max_interval = interval;
    }

  for(unsigned int i = 0; i < time_points.size(); i++)
    {
      Time_Point time_point = time_points.get(i);
      Atom current_point(time_point.as_text());

      Source_Interval interval(last_point, current_point);

      // Get the interval from the table first. If we hit this
      // interval multiple times, this will accumulate total time
      // spent in the interval.
      Delta_Time interval_time;
      (void) result->Get(interval, interval_time);

      interval_time += (time_point.delta - last_time);

      (void) result->Put(interval, interval_time);

      if(interval_time > max_time)
        {
          max_time = interval_time;
          max_interval = interval;
        }

      if((longid != 0) && (i == longid_start_point))
        {
          longid_interval = interval;
        }

      last_time = time_point.delta;
      last_point = current_point;
    }

  // Time to the end.

  Source_Interval interval(last_point, "end");
  Delta_Time interval_time = elapsed_time - last_time;
  (void) result->Put(interval, interval_time);

  if(interval_time > max_time)
    {
      max_time = interval_time;
      max_interval = interval;
    }

  if((longid != 0) && (time_points.size() == longid_start_point))
    {
      longid_interval = interval;
    }

  return result;
}

void Call_Data::longid_interval(/*OUT*/ Source_Interval &interval,
                                /*OUT*/ Delta_Time &time) const
{
  assert(longid != 0);

  Text start_point, end_point;
  Delta_Time start_time, end_time;
  if(longid_start_point == 0)
    {
      if(have_dupe)
        {
          start_point = "dupe";
          start_time = dupe_time;
        }
      else
        {
          start_point = "start";
        }
    }
  else
    {
      assert(longid_start_point <= time_points.size());

      Time_Point time_point = time_points.get(longid_start_point-1);
      start_point = time_point.as_text();
      start_time = time_point.delta;
    }

  if(longid_start_point < time_points.size())
    {
      Time_Point time_point = time_points.get(longid_start_point);
      end_point = time_point.as_text();
      end_time = time_point.delta;
    }
  else
    {
      end_point = "end";
      end_time = elapsed_time;
    }

  time = end_time - start_time;
  interval = Source_Interval(start_point, end_point);
}

typedef list<Call_Data,
             Basics::Allocator<Call_Data> > Call_List;

void sorted_slow_calls_insert(Call_List &slow_calls, const Call_Data &new_call)
{
#if 0
    Call_List::iterator start = slow_calls.begin();
    Call_List::iterator end = slow_calls.end();
    Call_List::iterator placement = start;
    int mid = slow_calls.size();

    while (start != end) {
        placement = start;
        mid = mid/2;
        for (int ii = 0; ii < mid; ii++) {
            ++placement;
        }
        if (new_call.elapsed_time > (*placement).elapsed_time) {
            start = placement;
            if (mid == 0 && start != end) {
                ++start;
            }
        } else {
            end = placement;
            if (mid == 0 && start != end) {
                --end;
            }
        }
    }
    placement = end;    
#else
    Call_List::iterator placement = lower_bound(slow_calls.begin(),
                                                slow_calls.end(),
                                                new_call);
#endif
    slow_calls.insert(placement, new_call);
}

static const char *NFS_proc_name(int proc)
{
  switch (proc)
    {
    case NFSPROC_NULL:
      return "null";
    case NFSPROC_GETATTR:
      return "getattr";
    case NFSPROC_SETATTR:
      return "setattr";
    case NFSPROC_ROOT:
      return "root";
    case NFSPROC_LOOKUP:
      return "lookup";
    case NFSPROC_READLINK:
      return "readlink";
    case NFSPROC_READ:
      return "read";
    case NFSPROC_WRITECACHE:
      return "writecache";
    case NFSPROC_WRITE:
      return "write";
    case NFSPROC_CREATE:
      return "create";
    case NFSPROC_REMOVE:
      return "remove";
    case NFSPROC_RENAME:
      return "rename";
    case NFSPROC_LINK:
      return "link";
    case NFSPROC_SYMLINK:
      return "symlink";
    case NFSPROC_MKDIR:
      return "mkdir";
    case NFSPROC_RMDIR:
      return "rmdir";
    case NFSPROC_READDIR:
      return "readdir";
    case NFSPROC_STATFS:
      return "statfs";
    }
  return "<INVALID>";
}

#define NUM_NFS_PROCS 18

struct Proc_Totals
{
  unsigned long count;
  Delta_Time time;
  Histogram time_histo;

  Call_List slowest_calls;

  LongId_Intervals slow_stable_longids, slow_volatile_longids;

  Proc_Totals()
    : count(0), time_histo(Log2)
  {
  }

  void add_call(const Call_Data &call)
  {
    // Increment totals
    this->time += call.elapsed_time;
    this->count++;

    // Figure out how many slow calls we want to keep.  (The real goal
    // is to get the slowest 1%, but in case the distributuion is
    // un-even, we keep more than 1%.)
    unsigned long two_percent_count =
      (unsigned long) ceil(((double)2*this->count)/100);
    unsigned long one_percent_plus_count = 
      (unsigned long) ceil(((double)this->count)/100);
    one_percent_plus_count += 20;

    unsigned long keep_count =
      ((one_percent_plus_count > two_percent_count)
       ? one_percent_plus_count
       : two_percent_count);

    // Store this in the slowest calls list if appropriate.
    if(this->slowest_calls.size() <
       keep_count)
      {
        sorted_slow_calls_insert(this->slowest_calls,
                                 call);
      }
    else if(call.elapsed_time >
            this->slowest_calls.front().elapsed_time)
      {
        sorted_slow_calls_insert(this->slowest_calls,
                                 call);
        this->slowest_calls.pop_front();
      }

    // If this call recorded a LongId...
    if(call.longid != 0)
      {
        // Get the source interval the LongId was recorded in (the
        // "interesting" one) and the time of that interval.
        Source_Interval lid_interval;
        Delta_Time lid_time;
        call.longid_interval(/*OUT*/ lid_interval,
                             /*OUT*/ lid_time);

        // Pick the right table of LongIds in slow intervals
        LongId_Intervals &lid_interval_table =
          (VolatileRootLongId.isAncestorOf(*(call.longid)))
          ? this->slow_volatile_longids
          : this->slow_stable_longids;

        // Get the list of LongIds recorded for this interval
        LongId_Point_List *lid_points = 0;
        bool inTbl = lid_interval_table.Get(lid_interval, lid_points);
        if(!inTbl)
          {
            // Create the list
            lid_points = NEW(LongId_Point_List);
            (void) lid_interval_table.Put(lid_interval, lid_points);
          }
        
        // Insert into the list if it makes sense to do so.
        if((lid_points->size() < keep_count) ||
           (lid_time > lid_points->front().time))
          {
            LongId_Point new_point = LongId_Point(call.longid, lid_time);
            LongId_Point_List::iterator placement =
              lower_bound(lid_points->begin(),
                          lid_points->end(),
                          new_point);
            lid_points->insert(placement, new_point);
          }

        // Prune the points
        if(lid_points->size() > keep_count)
          {
            lid_points->pop_front();
          }
      }

    // Record this call's elapsed time in the histogram.
    this->time_histo.AddVal((unsigned int) floor(call.elapsed_time.msecs()));
  }

  void merge(struct Proc_Totals &other)
  {
    this->time += other.time;
    this->count += other.count;
    this->time_histo += other.time_histo;

    this->slowest_calls.merge(other.slowest_calls);

    // Merge slow LongId data
    Source_Interval longid_interval;
    LongId_Point_List *their_point_list;
    {
      LongId_Intervals_Iter lid_it(&(other.slow_stable_longids));
      while(lid_it.Next(longid_interval, their_point_list))
        {
          LongId_Point_List *my_point_list;
          if(this->slow_stable_longids.Get(longid_interval,
                                           /*OUT*/ my_point_list))
            {
              // We already have a list for this source interval:
              // merge their list into ours.
              my_point_list->merge(*their_point_list);
            }
          else
            {
              // We don't have a list for this source interval: take
              // theirs as ours.
              this->slow_stable_longids.Put(longid_interval, their_point_list);
            }
        }
    }
    {
      LongId_Intervals_Iter lid_it(&(other.slow_volatile_longids));
      while(lid_it.Next(longid_interval, their_point_list))
        {
          LongId_Point_List *my_point_list;
          if(this->slow_volatile_longids.Get(longid_interval,
                                           /*OUT*/ my_point_list))
            {
              // We already have a list for this source interval:
              // merge their list into ours.
              my_point_list->merge(*their_point_list);
            }
          else
            {
              // We don't have a list for this source interval: take
              // theirs as ours.
              this->slow_volatile_longids.Put(longid_interval,
                                              their_point_list);
            }
        }
    }
  }
};

// Lifted from VLogHelp.C
ostream&
operator<<(ostream& s, const LongId& longid)
{
    int i;
    int len = longid.length();
    for (i=0; i<len; i++) {
        s << setw(2) << setfill('0') << hex
          << (int) (longid.value.byte[i] & 0xff);
    }
    s << setfill(' ') << dec;
    return s;
}

static void display_LongId(const LongId& longid, const char *indent, ostream& out)
{
  // First just print the raw LongId
  out << indent << longid << endl;

  // If this is in the appendable or mutable roots, try to look it up
  if((longid.value.byte[0] != 0) ||
     ((longid.value.byte[0] == 0) && (longid.value.byte[1] == 1)))
    {
      try
        {
          // The object in question may have been deleted.  If looking
          // it up fails, we look up its parent.  We repeat this until
          // we find an object that exists.
          LongId current = longid;
          unsigned int missing = 0;
          VestaSource *source = 0;
          while((source = current.lookup()) == 0)
            {
              current = current.getParent();
              missing++;
            }

          out << indent << ReposUI::vsToFilename(source);
          for(unsigned int printed = 0; missing > printed; printed++)
            {
              out << "/<deleted" << printed+1 << ">";
            }
          out << endl;
        }
      catch(...)
        {
          out <<  indent << "(exception caught while trying to get more information)"
              << endl;
        }
    }
  // In the volatile root
  else if((longid.value.byte[0] == 0) && (longid.value.byte[1] == 2))
    {
      out << indent << "<volatile root>";

      if(longid.value.byte[2] != 0)
        {
          // Climb up until we find the volatile root, counting the
          // directory depth and remembering the last index.
          LongId current = longid;
          unsigned int children = 0;
          unsigned int index = 0;
          while(!(current == VolatileRootLongId))
            {
              current = current.getParent(&index);
              children++;
            }
          char first_arc[(sizeof(index) * 2) + 1];
          sprintf(first_arc, "%08x", index);
          out << "/" << first_arc;
          for(unsigned int printed = 1; children > printed; printed++)
            {
              out << "/<arc" << printed << ">";
            }
        }

      out << endl;
    }
  // Directory shortid
  else if((longid.value.byte[0] == 0) && (longid.value.byte[1] == 3))
    {
      LongId current = longid;
      unsigned int index = 0;
      while(!(current == DirShortIdRootLongId))
        {
          current = current.getParent(&index);
        }
      out << indent << "<directory shortid 0x" << hex << index << ">" << endl;
    }
  // File shortid
  else if((longid.value.byte[0] == 0) && (longid.value.byte[1] == 4))
    {
      LongId current = longid;
      unsigned int index = 0;
      while(!(current == FileShortIdRootLongId))
        {
          current = current.getParent(&index);
        }
      out << indent << "<file shortid 0x" << hex << index << ">" << endl;
    }
  // NullLongId
  else if((longid.value.byte[0] == 0) && (longid.value.byte[1] == 255))
    {
      out << indent << "<null LongId>" << endl;
    }
}

static const char *program_name;

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

void parse(int optind, int argc, char * const argv[], Proc_Totals totals[]) {

  Proc_Totals* tot[NUM_NFS_PROCS];
  for(int proc = 0; proc < NUM_NFS_PROCS; proc++) { 
      tot[proc] = NEW_ARRAY(Proc_Totals, argc-optind);
  }

  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;

      try
        {
          while(1)
            {
              Call_Data next_call(stream);

              // Skip duplicates
              if(next_call.have_dupe && next_call.duplicate)
                continue;

              int proc = next_call.proc;
              assert(proc < NUM_NFS_PROCS);

              // Store data about this call
              tot[proc][arg-optind].add_call(next_call);

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

      cout << argv[arg] << ": " << file_count << " non-duplicate calls"
           << endl;

      int gunzip_status = pclose(stream);
      cout << "gunzip status: " << gunzip_status << endl;
  } 

  for(int proc = 0; proc < NUM_NFS_PROCS; proc++) { 
      for(int arg = 0; arg < argc-optind; arg++) {
        totals[proc].merge(tot[proc][arg]);
#if 0
          totals[proc].time += tot[proc][arg].time;
          totals[proc].count += tot[proc][arg].count;
          totals[proc].time_histo += tot[proc][arg].time_histo;

          totals[proc].slowest_calls.merge(tot[proc][arg].slowest_calls);
#endif
      }
      delete [] tot[proc];
  }

}

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

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

  Proc_Totals totals[NUM_NFS_PROCS];
  parse(optind, argc, argv, totals);

  // File used to generate a text report from the data.
  Text report_fname(output_prefix);
  report_fname += ".report";
  ofstream report(report_fname.cchars());

  // Used to accumulate histogram of call timing across all
  // procedures.
  Histogram all_time_histo(Log2);

  OBufStream all_histo_plot_args;

  for(int proc = 0; proc < NUM_NFS_PROCS; proc++)
    {
      if(totals[proc].count > 0)
        {
          const char *proc_name = NFS_proc_name(proc);

          double total_ms = totals[proc].time.msecs();
          report << proc_name << ":" << endl
                 << "\tcount        = " << totals[proc].count << endl
                 << "\ttotal time   = " << total_ms << " ms" << endl
                 << "\tslowest time = "
                 << totals[proc].slowest_calls.back().elapsed_time.msecs()
                 << " ms" << endl
                 << "\taverage time = " << (total_ms/totals[proc].count)
                 << " ms" << endl;

          // Generate histogram data file for this procedure.
          Text histo_base_fname(output_prefix);
          histo_base_fname += ".";
          histo_base_fname += proc_name;
          histo_base_fname += "_histo";
          Text histo_data_fname(histo_base_fname + ".dat");
          ofstream histo_data(histo_data_fname.cchars());

          totals[proc].time_histo.PrintHisto(histo_data);

          // gnuplot instructions for graphing the histogram of call
          // time.
          Text histo_gnuplot_fname(histo_base_fname + ".gnuplot");
          ofstream histo_gnuplot(histo_gnuplot_fname.cchars());

          histo_gnuplot << "set data style linespoints" << endl
                        << "set term png color" << endl
                        << "set title \"" << proc_name
                        << " turnaround time\"" << endl
                        << "set output \"" << histo_base_fname
                        << ".png\"" << endl
                        << "set xlabel \"ceil(log_2(time in ms))\"" << endl
                        << "set ylabel \"# calls\"" << endl
                        << "set logscale y" << endl
                        << "plot \"" << histo_data_fname << "\"" << endl;

          all_histo_plot_args << ", \"" << histo_data_fname
                              << "\" title \"" << proc_name << "\"";

          // Accumulate histogram data across all calls.
          all_time_histo += totals[proc].time_histo;

          // Throw out all but the slowest 1%
          unsigned long one_percent_count =
            (unsigned long) ceil(((double)totals[proc].count)/100);
          while(totals[proc].slowest_calls.size() > one_percent_count)
            {
              totals[proc].slowest_calls.pop_front();
            }

          report << "\tslowest 1% (" << one_percent_count << " calls):"
                 << totals[proc].slowest_calls.front().elapsed_time.msecs()
                 << " ms - "
                 << totals[proc].slowest_calls.back().elapsed_time.msecs()
                 << " ms" << endl;

          Interval_Counts max_interval_counts;
          unsigned int size_hint =
            totals[proc].slowest_calls.front().time_points.size();
          Interval_Times aggregate_interval_times(size_hint, true);
          Delta_Time total_time;

          Interval_Times interval_min_times(size_hint, true);
          Interval_Times interval_max_times(size_hint, true);

          Interval_Histos interval_histos(size_hint, true);

#ifdef LONGIDS_FROM_SLOWEST_CALLS
          LongId_Intervals longid_intervals(size_hint, true);
#endif

          for(Call_List::iterator it = totals[proc].slowest_calls.begin();
              it != totals[proc].slowest_calls.end();
              it++)
            {
              // Determine the interval times and slowest interval for
              // this call.
              Source_Interval max_interval, longid_interval;
              Interval_Times *cur_interval_times =
                (*it).compute_interval_times(/*OUT*/ max_interval,
                                             /*OUT*/ longid_interval);

              // Increment the count for the slowest interval.
              unsigned long interval_count = 0;
              (void) max_interval_counts.Get(max_interval, interval_count);
              interval_count++;
              (void) max_interval_counts.Put(max_interval, interval_count);

              // Accumulate interval times.
              aggregate_interval_times += *cur_interval_times;

              // Record the minimum and maximum time for each
              // interval, and record histogram data for each
              // interval.
              Interval_Times_Iter cur_times_iter(cur_interval_times);
              Source_Interval interval;
              Delta_Time interval_time;
              while(cur_times_iter.Next(interval, interval_time))
                {
                  Delta_Time table_time;
                  bool inTbl = interval_min_times.Get(interval, table_time);
                  if(!inTbl)
                    {
                      // First time seeing this interval, record this
                      // time as both the min and max for this
                      // interval.
                      (void) interval_min_times.Put(interval, interval_time);
                      (void) interval_max_times.Put(interval, interval_time);
                    }
                  else
                    {
                      if(table_time > interval_time)
                        {
                          // New minimum for this interval
                          (void) interval_min_times.Put(interval, interval_time);
                        }
                      inTbl = interval_max_times.Get(interval, table_time);
                      assert(inTbl);
                      if(interval_time > table_time)
                        {
                          // New maximum for this interval
                          (void) interval_max_times.Put(interval, interval_time);
                        }
                    }

                  // Get or create the interval time histogram
                  Histogram *interval_histo = 0;
                  inTbl = interval_histos.Get(interval, interval_histo);
                  if(!inTbl)
                    {
                      interval_histo = NEW_CONSTR(Histogram, (Log2));
                      (void) interval_histos.Put(interval, interval_histo);
                    }
                  assert(interval_histo != 0);

                  // Add this value to the histogram
                  interval_histo->AddVal((unsigned int)
                                         floor(interval_time.msecs()));
                }


#ifdef LONGIDS_FROM_SLOWEST_CALLS
              // If this call has a LongId recorded...
              if((*it).longid != 0)
                {
                  // Get the time in the interval that contained the recorded LongId.
                  Delta_Time longid_time;
                  bool inTbl = cur_interval_times->Get(longid_interval, longid_time);

                  // As long as it was there and took a noticable amount of time...
                  if(inTbl && (longid_time.msecs() > 1))
                    {
                      // Get the sequence of Longid/Time pairs.
                      LongId_Point_List *longid_times = 0;
                      inTbl = longid_intervals.Get(longid_interval, longid_times);
                      if(!inTbl)
                        {
                          longid_times = NEW(LongId_Point_List);
                          (void) longid_intervals.Put(longid_interval, longid_times);
                        }

                      longid_times->push_back(LongId_Point((*it).longid, longid_time));
                    }
                }
#endif

              // Accumulate total time.
              total_time += (*it).elapsed_time;
            }

          report << "\tslowest intervals in slowest 1%:" << endl;

          // Sort the keys of max_interval_counts by number
          
          Source_Interval *intervals =
            table_keys<Source_Interval, unsigned long>(max_interval_counts);
          sort(&intervals[0], &intervals[max_interval_counts.Size()],
               Interval_Count_Greater(max_interval_counts));

          // Print max_interval_counts sorted by number

          for(unsigned int i = 0; i < max_interval_counts.Size(); i++)
            {
              unsigned long count;
              bool inTbl = max_interval_counts.Get(intervals[i], count);
              assert(inTbl);
              report << "\t\t" << intervals[i] << ": " << count
                     << " (" << (count * 100/((double) one_percent_count))
                     << "% of slowest 1% calls)" << endl;
            }

          report << "\ttotal time spent in all intervals in slowest 1%:"
                 << endl;

          // Sort the keys of aggregate_interval_times by number

          intervals = table_keys<Source_Interval, Delta_Time>(aggregate_interval_times);
          sort(&intervals[0], &intervals[aggregate_interval_times.Size()],
               Interval_Time_Greater(aggregate_interval_times));

          // Print aggregate_interval_times sorted by time

          for(unsigned int i = 0; i < aggregate_interval_times.Size(); i++)
            {
              Delta_Time time;
              bool inTbl = aggregate_interval_times.Get(intervals[i], time);
              assert(inTbl);

              report << "\t\t" << intervals[i] << ": " << time.msecs()
                     << " ms (" << (time.msecs() * 100/total_time.msecs())
                     << "% of slowest 1% total time)" << endl;
            }

          report << "\trange of time time spent in all intervals in slowest 1%:"
                 << endl;

          // Sort the keys of interval_max_times by max time.

          intervals = table_keys<Source_Interval, Delta_Time>(interval_max_times);
          sort(&intervals[0], &intervals[interval_max_times.Size()],
               Interval_Time_Greater(interval_max_times));

          // Print interval_min_times and interval_max_times sorted by
          // max time

          for(unsigned int i = 0; i < interval_max_times.Size(); i++)
            {
              Delta_Time min_time, max_time;
              bool inTbl = interval_min_times.Get(intervals[i], min_time);
              assert(inTbl);
              inTbl = interval_max_times.Get(intervals[i], max_time);
              assert(inTbl);

              report << "\t\t" << intervals[i] << ": " << min_time.msecs()
                     << " ms - " << max_time.msecs()
                     << " ms" << endl;
            }

#ifdef LONGIDS_FROM_SLOWEST_CALLS
          report << "\tLongIds recorded for intervals in slowest 1%:"
                 << endl;

          Source_Interval longid_interval;
          LongId_Point_List *longid_point_seq;
          LongId_Intervals_Iter lid_it(&longid_intervals);
          while(lid_it.Next(longid_interval, longid_point_seq))
            {
              assert(longid_point_seq != 0);
              report << "\t\t" << longid_interval<< ":" << endl;

              // Turn the sequence into an array and then sort it by
              // elapsed time.
              unsigned int lid_point_count = longid_point_seq->size();
              LongId_Point *lid_points = NEW_ARRAY(LongId_Point,
                                                   lid_point_count);
              unsigned int i = 0;
              for(LongId_Point_List::iterator lid_list_it =
                    longid_point_seq->begin();
                  lid_list_it != longid_point_seq->end();
                  lid_list_it++, i++)
                {
                  lid_points[i] = *lid_list_it;
                }
              sort(&lid_points[0], &lid_points[lid_point_count],
                   LongId_Point_Slower);

              // Print out the elapsed times and the LongIds.
              for(unsigned int i = 0; i < lid_point_count; i++)
                {
                  report << "\t\t  " << lid_points[i].time.msecs() << endl;
                  display_LongId(*(lid_points[i].longid), "\t\t    ", report);
                }
            }
#endif

          report << "\tSlowest StableLock LongId intervals recorded:"
                 << endl;
          Source_Interval longid_interval;
          LongId_Point_List *longid_point_list; 
          LongId_Intervals_Iter lid_it(&(totals[proc].slow_stable_longids));
          while(lid_it.Next(longid_interval, longid_point_list))
            {
              assert(longid_point_list != 0);
              report << "\t\t" << longid_interval << ":" << endl
                     << "\t\t  [" << longid_point_list->size() << " total]"
                     << endl
                     << "\t\t  [longest: "
                     << longid_point_list->back().time.msecs() << " ms]"
                     << endl;

              unsigned int
                report_limit = totals[proc].count / 100,
                reported = 0;
              // Loop over the LongIds going back until we reach the
              // end of the list, or we reach one that's less than 1
              // ms, or we report on more than 1% of the calls in this
              // category.
              LongId_Point_List::iterator it = longid_point_list->end();
              while(it != longid_point_list->begin())
                {
                  it--;
                  if((*it).time.msecs() <= 1)
                    {
                      report << "\t\t  [stopping listing at sub-ms time]"
                             << endl;
                      break;
                    }
                  if(reported >= report_limit)
                    {
                      report << "\t\t  [stopping at report limit of "
                             << report_limit << " LongIds]" << endl;
                      break;
                    }
                  // Report this LongId
                  report << "\t\t  " << (*it).time.msecs() << " ms" << endl;
                  display_LongId(*((*it).longid), "\t\t    ", report);
                  reported++;
                }
            }

          // Generate datafiles and gnuplot instructions for
          // histograms of the source interval times in the slowest
          // 1%.  (We'll re-use the keys from interval_max_times to
          // generate these.)
          OBufStream interval_plot_args;
          bool first_interval_histo = true;
          unsigned int i;
          for(i = 0; i < interval_max_times.Size(); i++)
            {
              // Stop when we reach an interval with a maximum time of
              // less than 1 ms, as its histogram will be
              // uninteresting.
              Delta_Time max_time;
              bool inTbl = interval_max_times.Get(intervals[i], max_time);
              assert(inTbl);
              if(max_time.msecs() < 1)
                {
                  break;
                }

              // Get the interval histogram
              Histogram *interval_histo;
              inTbl = interval_histos.Get(intervals[i], interval_histo);
              assert(inTbl);
              assert(interval_histo != 0);

              // Generate data filename
              Text interval_histo_data_fname(output_prefix);
              interval_histo_data_fname += ".slow_";
              interval_histo_data_fname += proc_name;
              interval_histo_data_fname += "_";
              interval_histo_data_fname += intervals[i].as_fname();
              interval_histo_data_fname += ".dat";

              // Store the data
              ofstream interval_histo_data(interval_histo_data_fname.cchars());
              interval_histo->PrintHisto(interval_histo_data);

              // Remember this data file for the gnuplot instructions.
              if(!first_interval_histo)
                {
                  interval_plot_args << ", ";
                }
              interval_plot_args
                << "\"" << interval_histo_data_fname
                << "\" title \"" << intervals[i].as_text() << "\"";
              first_interval_histo = false;
            }

          // If we actually found more than one interesting interval
          if(!first_interval_histo && (i > 1))
            {
              Text interval_histo_base_fname(output_prefix);
              interval_histo_base_fname += ".slow_";
              interval_histo_base_fname += proc_name;
              interval_histo_base_fname += "_histo";
              Text interval_histo_gnuplot_fname(interval_histo_base_fname);
              interval_histo_gnuplot_fname += ".gnuplot";
              ofstream interval_histo_gnuplot(interval_histo_gnuplot_fname.cchars());

              interval_plot_args;
              interval_histo_gnuplot
                << "set data style linespoints" << endl
                << "set term png color" << endl
                << "set title \"interval times in slow " << proc_name
                << " calls\"" << endl
                << "set output \"" << interval_histo_base_fname
                << ".png\"" << endl
                << "set xlabel \"ceil(log_2(time in ms))\"" << endl
                << "set ylabel \"# calls\"" << endl
                << "set logscale y" << endl
                << "plot " << interval_plot_args.str() << endl;
            }
        }
    }

  // Generate histogram data for all procedures.
  Text histo_base_fname(output_prefix);
  histo_base_fname += ".all_procs_histo";
  Text histo_data_fname(histo_base_fname + ".dat");
  ofstream histo_data(histo_data_fname.cchars());

  all_time_histo.PrintHisto(histo_data);

  // gnuplot instructions for graphing the histogram of call
  // time.
  Text histo_gnuplot_fname(histo_base_fname + ".gnuplot");
  ofstream histo_gnuplot(histo_gnuplot_fname.cchars());

  histo_gnuplot << "set data style linespoints" << endl
                << "set term png color" << endl
                << "set title \"turnaround time for all NFS procedures\""
                << endl
                << "set output \"" << histo_base_fname
                << ".png\"" << endl
                << "set xlabel \"ceil(log_2(time in ms))\"" << endl
                << "set ylabel \"# calls\"" << endl
                << "set logscale y" << endl
                << "plot \"" << histo_data_fname << "\" title \"all\"";

  all_histo_plot_args;

  histo_gnuplot << all_histo_plot_args.str() << endl;

  return 0;
}

---