SimpleProfiler.cc

Go to the documentation of this file.

#ifndef _POSIX_C_SOURCE
#define _POSIX_C_SOURCE 199309
#endif

#if __linux
# include <execinfo.h>
# include <ucontext.h>
# include <sys/syscall.h>
#endif
#if __APPLE__
#include <signal.h>
//the following is needed to use the deprecated ucontext method on OS X
#define _XOPEN_SOURCE
#endif


#include <pthread.h>
#include <unistd.h>
#include <dlfcn.h>

#include <cassert>
#include <cstdio>
#include <cstring>
#include <iostream>
#include <sstream>
#include <stdexcept>

#include <sys/time.h>
#include <sys/stat.h>
#include <sys/resource.h>
#include <fcntl.h>
#include <ucontext.h>
#include <execinfo.h>

#include "SimpleProfiler.h"
#include "ProfParse.h"

#ifdef __linux
#ifndef __USE_POSIX199309
#error "SimpleProfile requires the definition of __USE_POSIX199309"
#endif
#endif


namespace INSTR
{
  typedef unsigned char byte;
  const byte RET = 0xc3;  
}

namespace
{

  std::string makeFileName()
  {
    pid_t p = getpid();
    std::ostringstream ost;
    ost << "profdata_" << p;
    return ost.str();
  }
}

// ---------------------------------------------------------------------
// Macros, for this compilation unit only
// ---------------------------------------------------------------------

#define MUST_BE_ZERO(fun) if((fun)!=0) { perror("function failed"); abort(); }
#define getBP(X)  asm ( "movl %%ebp,%0" : "=m" (X) )
#define getSP(X)  asm ( "movl %%esp,%0" : "=m" (X) )

#if 0
#define DODEBUG if(1) std::cerr
#else
#define DODEBUG if(0) std::cerr
#endif



#ifndef __USE_GNU
const int REG_EIP = 14;
const int REG_EBP = 6;
const int REG_ESP = 7;
#endif

#include "unistd.h"
#include <sstream>
#include <fstream>


namespace 
{

  // Record the dynamic library mapping information from /proc/ for
  // later use in discovering the names of functions recorded as
  // 'unknown_*'.
  void write_maps()
  {
    pid_t pid = getpid();
    std::ostringstream strinput,stroutput;
    strinput << "/proc/" << pid << "/maps";
    stroutput << "profdata_" << pid << "_maps";
    std::ifstream input(strinput.str().c_str());
    std::ofstream output(stroutput.str().c_str());
    std::string line;
    while (getline(input, line)) output << line << '\n';
    input.close();
    output.close();
  }

  FILE* frame_cond = 0;

  void openCondFile()
  {
    std::string filename(makeFileName());
    filename += "_condfile";
    frame_cond = fopen(filename.c_str(),"w");
    if(frame_cond==0)
      {
    std::cerr << "bad open of profdata_condfile\n";
    throw std::runtime_error("bad open");
      }
  }

  void writeCond(int code)
  {
    fwrite(&code,sizeof(int),1,frame_cond);
  }

  void closeCondFile()
  {
    fclose(frame_cond);
  }

  void dumpStack(const char* msg,
         unsigned int* esp, unsigned int* ebp, unsigned char* eip,
         ucontext_t* ucp)
  {
#if defined(__x86_64__) || defined(__LP64__) || defined(_LP64)
    throw std::logic_error("Cannot dumpStack on 64 bit build");
#else
    fprintf(frame_cond, msg);
    fflush(frame_cond);
    return;
    fprintf(frame_cond, "dumpStack:\n i= %p\n eip[0]= %2.2x\nb= %p\n s= %p\n b[0]= %x\n b[1]= %x\n b[2]= %x\n",
        eip, eip[0], (void *)ebp, (void *)esp, ebp[0], ebp[1], ebp[2]);
    fflush(frame_cond);


#if 0
    unsigned int* spp = esp;
    for(int i=15;i>-5;--i)
      {
    fprintf(frame_cond, "    %x esp[%d]= %x\n", (void*)(spp+i), i, (void*)*(spp+i));
    fflush(frame_cond);
      }
#else
    while(ucp->uc_link)
      {
    fprintf(frame_cond, "   %p\n", (void *)ucp->uc_link);
    ucp = ucp->uc_link;
      }
#endif
#endif
  }
}

namespace 
{
  // counters
  int samples_total=0;
  int samples_missing_framepointer=0;
}

// ---------------------------------------------------------------------
// This is the stack trace discovery code from IgHookTrace.
// ---------------------------------------------------------------------

#if __GNUC__ > 3 || (__GNUC__ == 3 && __GNUC_MINOR__ >= 4)
# define HAVE_UNWIND_BACKTRACE 1
#endif
#if !defined MAP_ANONYMOUS && defined MAP_ANON
# define MAP_ANONYMOUS MAP_ANON
#endif

#if HAVE_UNWIND_BACKTRACE
struct IgHookTraceArgs { void **array; int count; int size; };
extern "C" {
  typedef unsigned _Unwind_Ptr __attribute__((__mode__(__pointer__)));
  struct _Unwind_Context;
  enum _Unwind_Reason_Code
    {
      _URC_NO_REASON = 0,
      _URC_FOREIGN_EXCEPTION_CAUGHT = 1,
      _URC_FATAL_PHASE2_ERROR = 2,
      _URC_FATAL_PHASE1_ERROR = 3,
      _URC_NORMAL_STOP = 4,
      _URC_END_OF_STACK = 5,
      _URC_HANDLER_FOUND = 6,
      _URC_INSTALL_CONTEXT = 7,
      _URC_CONTINUE_UNWIND = 8
    };

  typedef _Unwind_Reason_Code (*_Unwind_Trace_Fn) (_Unwind_Context *, void *);
  _Unwind_Reason_Code _Unwind_Backtrace (_Unwind_Trace_Fn, void *);
  _Unwind_Ptr _Unwind_GetIP (_Unwind_Context *);
}

#ifndef __linux
static _Unwind_Reason_Code
GCCBackTrace (_Unwind_Context *context, void *arg)
{
  IgHookTraceArgs *args = (IgHookTraceArgs *) arg;
  if (args->count >= 0 && args->count < args->size)
    args->array [args->count++] = (void *) _Unwind_GetIP (context);
  else
    return _URC_END_OF_STACK;
  return _URC_NO_REASON;
}
#endif
#endif


int stacktrace (void *addresses[], int nmax)
{
  ++samples_total;
#if __linux && __i386
# if ! __x86_64__
#  define PROBABLY_VSYSCALL_PAGE 0xffff0000
# else
#  define PROBABLY_VSYSCALL_PAGE 0xffffffff00000000
# endif
  struct frame
  {
    // Normal frame.
    frame       *ebp;
    void        *eip;
    // Signal frame stuff, put in here by kernel.
    int     signo;
    siginfo_t   *info;
    ucontext_t  *ctx;
  };
  // register frame      *ebp __asm__ ("ebp");
  // register frame      *esp __asm__ ("esp");
  // use macros to avoid compiler warning.
#define getBP(X)  asm ( "movl %%ebp,%0" : "=m" (X) )
#define getSP(X)  asm ( "movl %%esp,%0" : "=m" (X) )
  register frame* ebp = 0;
  getBP(ebp);
  register frame* esp = 0;
  getSP(esp);

  frame               *fp = ebp;
  int           depth = 0;

  // Add fake entry to be compatible with other methods
  if (depth < nmax) addresses[depth++] = reinterpret_cast<void *>(reinterpret_cast<unsigned long>(&stacktrace));

  // Top-most frame ends with null pointer; check the rest is reasonable
  while (depth < nmax && fp >= esp)
    {
      // Add this stack frame.  The return address is the
      // instruction immediately after the "call".  The call
      // instruction itself is 4 or 6 bytes; we guess 4.
      addresses[depth++] = (char *) fp->eip - 4;

      // Recognise signal frames.  We use two different methods
      // depending on the linux kernel version.
      //
      // For the "old" kernels / systems we check the instructions
      // at the caller's return address.  We take it to be a signal
      // frame if we find the signal return code sequence there
      // and the thread register context structure pointer:
      //
      //    mov $__NR_rt_sigreturn, %eax
      //    int 0x80
      //
      // For the "new" kernels / systems the operating system maps
      // a "vsyscall" page at a high address, and it may contain
      // either the above code, or use of the sysenter/sysexit
      // instructions.  We cannot poke at that page so we take the
      // the high address as an indication this is a signal frame.
      // (http://www.trilithium.com/johan/2005/08/linux-gate/)
      // (http://manugarg.googlepages.com/systemcallinlinux2_6.html)
      //
      // If we don't recognise the signal frame correctly here, we
      // lose one stack frame: signal delivery is not a call so
      // when the signal handler is entered, ebp still points to
      // what it was just before the signal.
      unsigned char *insn = (unsigned char *) fp->eip;
      if (insn
      && insn[0] == 0xb8 && insn[1] == __NR_rt_sigreturn
      && insn[5] == 0xcd && insn[6] == 0x80
      && fp->ctx)
        {   
      void *retip = (void *) fp->ctx->uc_mcontext.gregs [REG_EIP];
      if (depth < nmax) addresses[depth++] = retip;

      fp = (frame *) fp->ctx->uc_mcontext.gregs [REG_EBP];
      if (fp && (unsigned long) retip > PROBABLY_VSYSCALL_PAGE)
        {
          // __kernel_vsyscall stack on system call exit is
          // [0] %ebp, [1] %edx, [2] %ecx, [3] return address.
          if (depth < nmax) addresses[depth++] = ((void **) fp)[3];
          fp = fp->ebp;

          // It seems the frame _above_ __kernel_syscall (the
          // syscall implementation in libc, such as __mmap())
          // is essentially frame-pointer-less, so we should
          // find also the call above, but I don't know how
          // to determine how many arguments the system call
          // pushed on stack to call __kernel_syscall short
          // of interpreting the DWARF unwind information :-(
          // So we may lose one level of call stack here.
          ++samples_missing_framepointer;
        }
        }

      // Otherwise it's a normal frame, process through frame pointer.
      else
    fp = fp->ebp;
    }

  return depth;
#elif __linux
  return backtrace (addresses, nmax);
#elif HAVE_UNWIND_BACKTRACE
  if (nmax >= 1)
    {
      IgHookTraceArgs args = { addresses, 0, nmax };
      _Unwind_Backtrace (&GCCBackTrace, &args);

      if (args.count > 1 && args.array [args.count-1] == 0)
    args.count--;

      return args.count;
    }
  return 0;
#else
  return 0;
#endif
}

// ---------------------------------------------------------------------
// The signal handler. We register this to handle the SIGPROF signal.
// ---------------------------------------------------------------------

extern "C" 
{
  void sigFunc(int sig, siginfo_t* info, void* context)
  {
    SimpleProfiler* prof = SimpleProfiler::instance();
    void** arr = prof->tempStack();
    int nmax =   prof->tempStackSize();
    int stackdepth = stacktrace(arr, nmax);

    assert(stackdepth <= nmax);

    // We don't want the first three entries, because they always
    // contain information about the how the signal handler was
    // called, the signal handler, and the stacktrace function.
    prof->commitFrame(arr+3, arr + stackdepth);
  }
}

namespace
{
  
#if USE_SIGALTSTACK
  stack_t ss_area;
#endif

  void setupTimer();

  void* setStacktop()
  {
#if defined(__x86_64__) || defined(__LP64__) || defined(_LP64)
    throw std::logic_error("setStacktop not callable on 64 bit platform");
    return 0;
#else
    const std::string target_name("__libc_start_main");
    unsigned int* ebp_reg;
    getBP(ebp_reg);
    unsigned int* ebp = (unsigned int*)(ebp_reg);
    unsigned int* top = (unsigned int*)(ebp);

    void* address_of_target = 0;
    const int max_stackdepth=30;
    void* sta[max_stackdepth];

    int depth = backtrace(sta, max_stackdepth);
    int cnt = depth;
    if (depth > 1) depth-=1;

    // find function one below main()
    Dl_info look;
    for (int i=0; i<cnt && !address_of_target; ++i)
      {
    if(dladdr(sta[i],&look)!=0)
      {
        if (look.dli_saddr && target_name==look.dli_sname)
          {
        address_of_target = sta[i];
          }
      }
    else
      {
        // This isn't really an error; it just means the function
        // was not found by the dynamic loader. The function might
        // be one that is declared 'static', and is thus not
        // visible outside of its compilation unit.
        std::cerr << "setStacktop: no function information for " 
              << sta[i] 
              << "\n";
      }
      }

    if (address_of_target == 0)
      throw std::runtime_error("no main function found in stack");

    //fprintf(stderr,"depth=%d top=%8.8x\n",depth,top);

    // Now we walk toward the beginning of the stack until we find the
    // frame that is holding the return address of our target function.

    // depth is how many more frames there are to look at in the stack.
    // top is the frame we are currently looking at.
    // top+1 is the address to which the current frame will return.
    while (depth>0 && (void*)*(top+1) != address_of_target)
      {
    //fprintf(stderr,"depth=%d top=%8.8x func=%8.8x\n",depth,top,*(top+1));
    if (top<(unsigned int*)0x10) fprintf(stderr,"problem\n");
    top=(unsigned int*)(*top);
    --depth;
      };

    if (depth==0) 
      throw std::runtime_error("setStacktop: could not find stack bottom");

    // Now we have to move one frame more, to the frame of the target
    // function. We want the location in memory of this frame (not any
    // address stored in the frame, but the address of the frame
    // itself).
    top=(unsigned int*)(*top);

    return top;
#endif
  }

  void setupTimer()
  {
#if USE_SIGALTSTACK
    static vector<char> charbuffer(SIGSTKSZ);
    //ss_area.ss_sp = new char[SIGSTKSZ];
    ss_area.ss_sp = &charbuffer[0];
    ss_area.ss_flags = 0;
    ss_area.ss_size = SIGSTKSZ;
#endif
    //static int is_set = 0;
    //if(is_set!=1) { ++is_set; return; }
    //else ++is_set;

    sigset_t myset,oldset;
    // all blocked for now
    MUST_BE_ZERO(sigfillset(&myset));
    MUST_BE_ZERO(pthread_sigmask(SIG_SETMASK,&myset,&oldset));

#if defined(__x86_64__) || defined(__LP64__) || defined(_LP64) 
#if __linux
    // ignore all the RT signals
    struct sigaction tmpact;
    memset(&tmpact,0,sizeof(tmpact));
    tmpact.sa_handler = SIG_IGN;

    for(int num=SIGRTMIN;num<SIGRTMAX;++num)
      {
    MUST_BE_ZERO(sigaddset(&oldset,num));
    MUST_BE_ZERO(sigaction(num,&tmpact,NULL));
      }
#endif
#endif

#if USE_SIGALTSTACK
    if(sigaltstack(&ss_area,0)!=0)
      {
    perror("sigaltstack failed for profile timer interrupt");
    abort();
      }
#endif

    // set up my RT signal now
    struct sigaction act;
    memset(&act,0,sizeof(act));
    act.sa_sigaction = sigFunc;
    act.sa_flags = SA_RESTART | SA_SIGINFO | SA_ONSTACK;

    // get my signal number
    int mysig = SIGPROF;

    if(sigaction(mysig,&act,NULL)!=0)
      {
    perror("sigaction failed");
    abort();
      }

    // Turn off handling of SIGSEGV signal
    memset(&act,0,sizeof(act));
    act.sa_handler = SIG_DFL;

    if (sigaction(SIGSEGV, &act, NULL) != 0)
      {
    perror("sigaction failed");
    abort();
      }

    struct rlimit limits;
    if (getrlimit(RLIMIT_CORE, &limits) != 0)
      {
    perror("getrlimit failed");
    abort();
      }
    std::cerr << "core size limit (soft): " << limits.rlim_cur << '\n';
    std::cerr << "core size limit (hard): " << limits.rlim_max << '\n';

    struct itimerval newval;
    struct itimerval oldval;

    newval.it_interval.tv_sec  = 0;
    newval.it_interval.tv_usec = 10000;
    newval.it_value.tv_sec  = 0;
    newval.it_value.tv_usec = 10000;

    if(setitimer(ITIMER_PROF,&newval,&oldval)!=0)
      {
    perror("setitimer failed");
    abort();
      }

    // reenable the signals, including my interval timer
    MUST_BE_ZERO(sigdelset(&oldset,mysig));
    MUST_BE_ZERO(pthread_sigmask(SIG_SETMASK,&oldset,0));
  }


  struct AdjustSigs
  {
    AdjustSigs()
    {
      sigset_t myset,oldset;
      // all blocked for now
      MUST_BE_ZERO(sigfillset(&myset));
      MUST_BE_ZERO(pthread_sigmask(SIG_SETMASK,&myset,&oldset));
    
      // ignore all the RT signals
      struct sigaction tmpact;
      memset(&tmpact,0,sizeof(tmpact));
      tmpact.sa_handler = SIG_IGN;
    
#if defined(__x86_64__) || defined(__LP64__) || defined(_LP64) 
#if __linux
      for(int num=SIGRTMIN;num<SIGRTMAX;++num)
    {
      MUST_BE_ZERO(sigaddset(&oldset,num));
      MUST_BE_ZERO(sigaction(num,&tmpact,NULL));
    }
#endif
#endif
    
      MUST_BE_ZERO(sigaddset(&oldset,SIGPROF));
      MUST_BE_ZERO(pthread_sigmask(SIG_SETMASK,&oldset,0));
    }
  };

  static AdjustSigs global_adjust;


}

SimpleProfiler* SimpleProfiler::inst_ = 0;
boost::mutex SimpleProfiler::lock_;


SimpleProfiler* SimpleProfiler::instance()
{
  if(SimpleProfiler::inst_ == 0)
    {
      boost::mutex::scoped_lock sl(lock_);
      if(SimpleProfiler::inst_ == 0)
    {
      static SimpleProfiler p;
      SimpleProfiler::inst_ = &p;
    }
    }
  return SimpleProfiler::inst_;
}

SimpleProfiler::SimpleProfiler():
  frame_data_(10*1000*1000),
  tmp_stack_(1000),
  high_water_(&frame_data_[10*1000*1000-10*1000]),
  curr_(&frame_data_[0]),
  filename_(makeFileName()),
  fd_(open(filename_.c_str(), 
       O_RDWR|O_CREAT,
       S_IRWXU|S_IRGRP|S_IROTH|S_IWGRP|S_IWOTH)),
  installed_(false),
  running_(false),
  owner_(),
  stacktop_(setStacktop())
{
  if (fd_ < 0) {
    std::ostringstream ost;
    ost << "failed to open profiler output file " << filename_;
    throw std::runtime_error(ost.str().c_str());
  }
  
  openCondFile();
}

SimpleProfiler::~SimpleProfiler()
{
  if (running_)
    std::cerr << "Warning: the profile timer was not stopped,\n"
          << "profiling data in " << filename_
          << " is probably incomplete and will not be processed\n";

  closeCondFile();
}

void SimpleProfiler::commitFrame(void** first, void** last)
{
  void** cnt_ptr = curr_; 
  *cnt_ptr = reinterpret_cast<void*>(std::distance(first,last));
  ++curr_;
  curr_ = std::copy(first,last,curr_);
  if(curr_ > high_water_) doWrite();
}

void SimpleProfiler::doWrite()
{
  void** start = &frame_data_[0];
  if(curr_ == start) return;
  unsigned int cnt = std::distance(start,curr_) * sizeof(void*);
  unsigned int totwr=0;

  while (cnt>0 && (totwr=write(fd_,start,cnt)) != cnt) {
    if(totwr==0) 
      throw std::runtime_error("SimpleProfiler::doWrite wrote zero bytes");
    start+=(totwr/sizeof(void*));
    cnt-=totwr;
  }

  curr_ = &frame_data_[0];
}

void SimpleProfiler::start()
{
#if defined(__x86_64__) || defined(__LP64__) || defined(_LP64)
  throw std::logic_error("SimpleProfiler not available on 64 bit platform");
#endif
  {
    boost::mutex::scoped_lock sl(lock_);

    if (installed_) {
      std::cerr << "Warning: second thread " << pthread_self()
        << " requested the profiler timer and another thread\n"
        << owner_ << "has already started it.\n"
        << "Only one thread can do profiling at a time.\n"
        << "This second thread will not be profiled.\n";
      return;
    }
    
    installed_ = true;
  }

  owner_ = pthread_self();
  setupTimer();
  running_ = true;
}

void SimpleProfiler::stop()
{
  if(!installed_)
    {
      std::cerr << "SimpleProfiler::stop - no timer installed to stop\n";
      return;
    }

  if(owner_ != pthread_self())
    {
      std::cerr << "SimpleProfiler::stop - only owning thread can stop the timer\n";
      return;
    }

  if(!running_)
    {
      std::cerr << "SimpleProfiler::stop - no timer is running\n";
      return;
    }

  struct itimerval newval;

  newval.it_interval.tv_sec  = 0;
  newval.it_interval.tv_usec = 0;
  newval.it_value.tv_sec  = 0;
  newval.it_value.tv_usec = 0;

  if(setitimer(ITIMER_PROF,&newval,0)!=0)
    {
      perror("setitimer call failed - could not stop the timer");
    }

  running_=false;
  complete();
}



void SimpleProfiler::complete()
{
  doWrite();

  if(lseek(fd_,0,SEEK_SET)<0)
    {
      std::cerr << "SimpleProfiler: could not seek to the start of the profile\n"
        << " data file during completion.  Data will be lost.\n";
      return;
    }

  writeProfileData(fd_,filename_);
  write_maps();

  std::string totsname = makeFileName();
  totsname += "_sample_info";
  std::ofstream ost(totsname.c_str());
  
  ost << "samples_total " << samples_total << "\n"
      << "samples_missing_framepointer " << samples_missing_framepointer << "\n" ;
}