trace.c

分布式文件系统

/*
   Copyright (c) 2006, 2007, 2008 Z RESEARCH, Inc. <http://www.zresearch.com>
   This file is part of GlusterFS.

   GlusterFS is free software; you can redistribute it and/or modify
   it under the terms of the GNU General Public License as published
   by the Free Software Foundation; either version 3 of the License,
   or (at your option) any later version.

   GlusterFS 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
   General Public License for more details.

   You should have received a copy of the GNU General Public License
   along with this program.  If not, see
   <http://www.gnu.org/licenses/>.
*/

#ifndef _CONFIG_H
#define _CONFIG_H
#include "config.h"
#endif

/**
 * xlators/debug/trace :
 *    This translator logs all the arguments to the fops/mops and also 
 *    their _cbk functions, which later passes the call to next layer. 
 *    Very helpful translator for debugging.
 */

#include <time.h>
#include <errno.h>
#include "glusterfs.h"
#include "xlator.h"

#define ERR_EINVAL_NORETURN(cond)                \
do                                               \
  {						 \
    if ((cond))					 \
      {						 \
	gf_log ("ERROR", 			 \
		GF_LOG_ERROR, 			 \
		"%s: %s: (%s) is true", 	 \
		__FILE__, __FUNCTION__, #cond);	 \
      }                                          \
  } while (0)

extern int32_t errno;

#define _FORMAT_WARN(domain, log_level, format, args...)  printf ("__DEBUG__" format, ##args);     

typedef struct trace_private
{
  int32_t debug_flag;
} trace_private_t;

struct {
  const char *name;
  int enabled;
} fop_names[] = {{"stat", 1},
		 {"readlink", 1},
		 {"mknod", 1},
		 {"mkdir", 1},
		 {"unlink", 1},
		 {"rmdir", 1},
		 {"symlink", 1},
		 {"rename", 1},
		 {"link", 1},
		 {"chmod", 1},
		 {"chown", 1},
		 {"truncate", 1},
		 {"open", 1},
		 {"read", 1},
		 {"write", 1},
		 {"statfs", 1},
		 {"flush", 1},
		 {"close", 1},
		 {"fsync", 1},
		 {"setxattr", 1},
		 {"getxattr", 1},
		 {"removexattr", 1},
		 {"opendir", 1},
		 {"getdents", 1},
		 {"closedir", 1},
		 {"fsyncdir", 1},
		 {"access", 1},
		 {"create", 1},
		 {"ftruncate", 1},
		 {"fstat", 1},
		 {"lk", 1},
		 {"utimens", 1},
		 {"fchmod", 1},
		 {"fchown", 1},
		 {"lookup", 1},
		 {"forget", 1},
		 {"setdents", 1},
		 {"rmelem", 1},
		 {"incver", 1},
		 {"readdir", 1},};

int32_t 
trace_create_cbk (call_frame_t *frame,
		  void *cookie,
		  xlator_t *this,
		  int32_t op_ret,
		  int32_t op_errno,
		  fd_t *fd,
		  inode_t *inode,
		  struct stat *buf)
{
  char atime_buf[256], mtime_buf[256], ctime_buf[256];
  ERR_EINVAL_NORETURN (!this);

  if (fop_names[GF_FOP_CREATE].enabled) {
    if (op_ret >= 0) {
      strftime (atime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_atime));
      strftime (mtime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_mtime));
      strftime (ctime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_ctime));

      gf_log (this->name, GF_LOG_NORMAL, 
	    "(*this=%s, op_ret=%d, op_errno=%d, fd=%p, inode=%p), *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld, st_atime=%s, st_mtime=%s, st_ctime=%s})",
	    this->name, op_ret, op_errno, fd, inode, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks, atime_buf, mtime_buf, ctime_buf);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }

  STACK_UNWIND (frame, op_ret, op_errno, fd, inode, buf);
  return 0;
}

int32_t 
trace_open_cbk (call_frame_t *frame,
		void *cookie,
		xlator_t *this,
		int32_t op_ret,
		int32_t op_errno,
		fd_t *fd)
{
  ERR_EINVAL_NORETURN (!this);

  if (fop_names[GF_FOP_OPEN].enabled) {
  gf_log (this->name, 
	  GF_LOG_NORMAL, 
	  "(*this=%p, op_ret=%d, op_errno=%d, *fd=%p)",
	  this, op_ret, op_errno, fd);
  }

  STACK_UNWIND (frame, op_ret, op_errno, fd);
  return 0;
}

int32_t 
trace_stat_cbk (call_frame_t *frame,
		void *cookie,
		xlator_t *this,
		int32_t op_ret,
		int32_t op_errno,
		struct stat *buf)
{
  char atime_buf[256], mtime_buf[256], ctime_buf[256];
  ERR_EINVAL_NORETURN (!this);
  
  if (fop_names[GF_FOP_STAT].enabled) {

  if (op_ret >= 0) {
    strftime (atime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_atime));
    strftime (mtime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_mtime));
    strftime (ctime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_ctime));

    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d, *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld, st_atime=%s, st_mtime=%s, st_ctime=%s})",
	    this, op_ret, op_errno, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks, atime_buf, mtime_buf, ctime_buf);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }    

  STACK_UNWIND (frame, op_ret, op_errno, buf);
  return 0;
}

int32_t 
trace_readv_cbk (call_frame_t *frame,
		 void *cookie,
		 xlator_t *this,
		 int32_t op_ret,
		 int32_t op_errno,
		 struct iovec *vector,
		 int32_t count,
		 struct stat *buf)
{
  char atime_buf[256], mtime_buf[256], ctime_buf[256];
  ERR_EINVAL_NORETURN (!this);

  if (fop_names[GF_FOP_READ].enabled) {

  if (op_ret >= 0) {
    strftime (atime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_atime));
    strftime (mtime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_mtime));
    strftime (ctime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_ctime));

    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d, *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld, st_atime=%s, st_mtime=%s, st_ctime=%s})",
	    this, op_ret, op_errno, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks, atime_buf, mtime_buf, ctime_buf);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }
  
  STACK_UNWIND (frame, op_ret, op_errno, vector, count, buf);
  return 0;
}

int32_t 
trace_writev_cbk (call_frame_t *frame,
		  void *cookie,
		  xlator_t *this,
		  int32_t op_ret,
		  int32_t op_errno,
		  struct stat *buf)
{
  char atime_buf[256], mtime_buf[256], ctime_buf[256];
  ERR_EINVAL_NORETURN (!this);

  if (fop_names[GF_FOP_WRITE].enabled) {
  if (op_ret >= 0) {
    strftime (atime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_atime));
    strftime (mtime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_mtime));
    strftime (ctime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_ctime));

    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d, *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld, st_atime=%s, st_mtime=%s, st_ctime=%s})",
	    this, op_ret, op_errno, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks, atime_buf, mtime_buf, ctime_buf);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }

  STACK_UNWIND (frame, op_ret, op_errno, buf);
  return 0;
}

int32_t 
trace_getdents_cbk (call_frame_t *frame,
		    void *cookie,
		    xlator_t *this,
		    int32_t op_ret,
		    int32_t op_errno,
		    dir_entry_t *entries,
		    int32_t count)
{
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_GETDENTS].enabled) {
  gf_log (this->name, 
	  GF_LOG_NORMAL, 
	  "(*this=%p, op_ret=%d, op_errno=%d, count=%d)",
	  this, op_ret, op_errno, count);
  }
  
  STACK_UNWIND (frame, op_ret, op_errno, entries, count);
  return 0;
}

int32_t 
trace_readdir_cbk (call_frame_t *frame,
		   void *cookie,
		   xlator_t *this,
		   int32_t op_ret,
		   int32_t op_errno,
		   gf_dirent_t *buf)
{
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_READDIR].enabled) {
  gf_log (this->name, 
	  GF_LOG_NORMAL, 
	  "(op_ret=%d, op_errno=%d)",
	  op_ret, op_errno);
  }
  
  STACK_UNWIND (frame, op_ret, op_errno, buf);

  return 0;
}

int32_t 
trace_fsync_cbk (call_frame_t *frame,
		 void *cookie,
		 xlator_t *this,
		 int32_t op_ret,
		 int32_t op_errno)
{
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_FSYNC].enabled) {
  gf_log (this->name, 
	  GF_LOG_NORMAL, 
	  "(*this=%p, op_ret=%d, op_errno=%d)",
	  this, op_ret, op_errno);
  }

  STACK_UNWIND (frame, op_ret, op_errno);
  return 0;
}

int32_t 
trace_chown_cbk (call_frame_t *frame,
		 void *cookie,
		 xlator_t *this,
		 int32_t op_ret,
		 int32_t op_errno,
		 struct stat *buf)
{
  char atime_buf[256], mtime_buf[256], ctime_buf[256];
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_CHOWN].enabled) {
  if (op_ret >= 0) {
    strftime (atime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_atime));
    strftime (mtime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_mtime));
    strftime (ctime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_ctime));
    
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d, *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld, st_atime=%s, st_mtime=%s, st_ctime=%s})",
	    this, op_ret, op_errno, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks, atime_buf, mtime_buf, ctime_buf);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }

  STACK_UNWIND (frame, op_ret, op_errno, buf);
  return 0;
}

int32_t 
trace_chmod_cbk (call_frame_t *frame,
		 void *cookie,
		 xlator_t *this,
		 int32_t op_ret,
		 int32_t op_errno,
		 struct stat *buf)
{
  char atime_buf[256], mtime_buf[256], ctime_buf[256];
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_CHMOD].enabled) {
  if (op_ret >= 0) {
    strftime (atime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_atime));
    strftime (mtime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_mtime));
    strftime (ctime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_ctime));
    
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d, *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld, st_atime=%s, st_mtime=%s, st_ctime=%s})",
	    this, op_ret, op_errno, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks, atime_buf, mtime_buf, ctime_buf);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }

  STACK_UNWIND (frame, op_ret, op_errno, buf);
  return 0;
}

int32_t 
trace_fchmod_cbk (call_frame_t *frame,
		  void *cookie,
		  xlator_t *this,
		  int32_t op_ret,
		  int32_t op_errno,
		  struct stat *buf)
{
  char atime_buf[256], mtime_buf[256], ctime_buf[256];
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_FCHMOD].enabled) {
  if (op_ret >= 0) {
    strftime (atime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_atime));
    strftime (mtime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_mtime));
    strftime (ctime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_ctime));
    
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d, *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld, st_atime=%s, st_mtime=%s, st_ctime=%s})",
	    this, op_ret, op_errno, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks, atime_buf, mtime_buf, ctime_buf);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }

  STACK_UNWIND (frame, op_ret, op_errno, buf);
  return 0;
}

int32_t 
trace_fchown_cbk (call_frame_t *frame,
		  void *cookie,
		  xlator_t *this,
		  int32_t op_ret,
		  int32_t op_errno,
		  struct stat *buf)
{
  char atime_buf[256], mtime_buf[256], ctime_buf[256];
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_FCHOWN].enabled) {  
  if (op_ret >= 0) {
    strftime (atime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_atime));
    strftime (mtime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_mtime));
    strftime (ctime_buf, 256, "[%b %d %H:%M:%S]", localtime (&buf->st_ctime));
    
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d, *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld, st_atime=%s, st_mtime=%s, st_ctime=%s})",
	    this, op_ret, op_errno, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks, atime_buf, mtime_buf, ctime_buf);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }

  STACK_UNWIND (frame, op_ret, op_errno, buf);
  return 0;
}

int32_t 
trace_unlink_cbk (call_frame_t *frame,
		  void *cookie,
		  xlator_t *this,
		  int32_t op_ret,
		  int32_t op_errno)
{
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_UNLINK].enabled) {
  gf_log (this->name, 
	  GF_LOG_NORMAL, 
	  "(*this=%p, op_ret=%d, op_errno=%d)",
	  this, op_ret, op_errno);
  }

  STACK_UNWIND (frame, op_ret, op_errno);
  return 0;
}

int32_t 
trace_rename_cbk (call_frame_t *frame,
		  void *cookie,
		  xlator_t *this,
		  int32_t op_ret,
		  int32_t op_errno,
		  struct stat *buf)
{
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_RENAME].enabled) {
  gf_log (this->name, 
	  GF_LOG_NORMAL, 
	  "(*this=%p, op_ret=%d, op_errno=%d, buf=%p)",
	  this, op_ret, op_errno, buf);
  }
  
  STACK_UNWIND (frame, op_ret, op_errno, buf);
  return 0;
}

int32_t 
trace_readlink_cbk (call_frame_t *frame,
		    void *cookie,
		    xlator_t *this,
		    int32_t op_ret,
		    int32_t op_errno,
		    const char *buf)
{
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_READLINK].enabled) {  
  gf_log (this->name, 
	  GF_LOG_NORMAL, 
	  "(*this=%p, op_ret=%d, op_errno=%d, buf=%s)",
	  this, op_ret, op_errno, buf);
  }

  STACK_UNWIND (frame, op_ret, op_errno, buf);
  return 0;
}

int32_t 
trace_lookup_cbk (call_frame_t *frame,
		  void *cookie,
		  xlator_t *this,
		  int32_t op_ret,
		  int32_t op_errno,
		  inode_t *inode,
		  struct stat *buf,
		  dict_t *xattr)
{
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_LOOKUP].enabled) {
  if (op_ret >= 0) {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "callid: %lld (*this=%p, op_ret=%d, op_errno=%d, inode=%p, *buf=%p {st_dev=%lld, st_ino=%lld, st_mode=%d, st_nlink=%d, st_uid=%d, st_gid=%d, st_rdev=%llx, st_size=%lld, st_blksize=%ld, st_blocks=%lld})",
	    (long long) frame->root->unique, this, op_ret, op_errno, inode, buf, buf->st_dev, buf->st_ino, buf->st_mode, buf->st_nlink, buf->st_uid, buf->st_gid, buf->st_rdev, buf->st_size, buf->st_blksize, buf->st_blocks);
  } else {
    gf_log (this->name, 
	    GF_LOG_NORMAL, 
	    "(*this=%p, op_ret=%d, op_errno=%d)",
	    this, op_ret, op_errno);
  }    
  }

  STACK_UNWIND (frame, op_ret, op_errno, inode, buf, xattr);
  return 0;
}

int32_t 
trace_forget_cbk (call_frame_t *frame,
		  void *cookie,
		  xlator_t *this,
		  int32_t op_ret,
		  int32_t op_errno)
{
  ERR_EINVAL_NORETURN (!this );

  if (fop_names[GF_FOP_FORGET].enabled) {
  gf_log (this->name, 
	  GF_LOG_NORMAL, 
	  "(*this=%p, op_ret=%d, op_errno=%d)",
	  this, op_ret, op_errno);
  }

  STACK_UNWIND (frame, op_ret, op_errno);
  return 0;
}

int32_t 
trace_symlink_cbk (call_frame_t *frame,
		   void *cookie,
		   xlator_t *this,
		   int32_t op_ret,
		   int32_t op_errno,
		   inode_t *inode,
		   struct stat *buf)