add more perf counter in FileStore::_do_transaction

more-perf_counter

diff -u -r ceph-0.67.3/src/os/FileStore.cc ceph-0.67.3-rongze/src/os/FileStore.cc
--- ceph-0.67.3/src/os/FileStore.cc     2013-09-09 19:47:34.000000000 +0000
+++ ceph-0.67.3-rongze/src/os/FileStore.cc      2013-12-17 04:16:28.964417431 +0000
@@ -473,6 +473,50 @@
   plb.add_time_avg(l_os_commit_lat, "commitcycle_latency");
   plb.add_u64_counter(l_os_j_full, "journal_full");
   plb.add_time_avg(l_os_queue_lat, "queue_transaction_latency_avg");
+  plb.add_time_avg(l_os_lfn_open_lat, "lfn_open_lat");
+  plb.add_time_avg(l_os_lseek_lat, "lseek_lat");
+  plb.add_time_avg(l_os_writefd_lat, "writefd_latency");
+  plb.add_time_avg(l_os_wbthrottle_queue_lat, "wbthrottle_latency");
+  plb.add_time_avg(l_os_do_op_lat, "do_op_latency");
+  plb.add_time_avg(l_os_do_transactions_lat, "do_transactions_latency");
+  plb.add_time_avg(l_os_do_transaction_lat, "do_transaction_latency");
+  plb.add_time_avg(l_os_write_lat, "write_latency");
+  plb.add_time_avg(l_os_tran_1_lat, "tran_1_latency");
+  plb.add_time_avg(l_os_tran_2_lat, "tran_2_latency");
+  plb.add_time_avg(l_os_tran_3_lat, "tran_3_latency");
+  plb.add_time_avg(l_os_tran_4_lat, "tran_4_latency");
+  plb.add_time_avg(l_os_op_touch_lat, "op_touch_lat");
+  plb.add_time_avg(l_os_op_write_lat, "op_write_lat");
+  plb.add_time_avg(l_os_op_zero_lat, "op_zero_lat");
+  plb.add_time_avg(l_os_op_trimcache_lat, "op_trimcache_lat");
+  plb.add_time_avg(l_os_op_truncate_lat, "op_truncate_lat");
+  plb.add_time_avg(l_os_op_remove_lat, "op_remove_lat");
+  plb.add_time_avg(l_os_op_setattr_lat, "op_setattr_lat");
+  plb.add_time_avg(l_os_op_setattrs_lat, "op_setattrs_lat");
+  plb.add_time_avg(l_os_op_rmattr_lat, "op_rmattr_lat");
+  plb.add_time_avg(l_os_op_rmattrs_lat, "op_rmattrs_lat");
+  plb.add_time_avg(l_os_op_clone_lat, "op_clone_lat");
+  plb.add_time_avg(l_os_op_clonerange_lat, "op_clonerange_lat");
+  plb.add_time_avg(l_os_op_clonerange2_lat, "op_clonerange2_lat");
+  plb.add_time_avg(l_os_op_mkcoll_lat, "op_mkcoll_lat");
+  plb.add_time_avg(l_os_op_rmcoll_lat, "op_rmcoll_lat");
+  plb.add_time_avg(l_os_op_coll_add_lat, "op_coll_add_lat");
+  plb.add_time_avg(l_os_op_coll_remove_lat, "op_coll_remove_lat");
+  plb.add_time_avg(l_os_op_coll_move_lat, "op_coll_move_lat");
+  plb.add_time_avg(l_os_op_coll_setattr_lat, "op_coll_setattr_lat");
+  plb.add_time_avg(l_os_op_coll_rmattr_lat, "op_coll_setattr_lat");
+  plb.add_time_avg(l_os_op_startsync_lat, "op_coll_setattr_lat");
+  plb.add_time_avg(l_os_op_coll_rename_lat, "op_coll_rename_lat");
+  plb.add_time_avg(l_os_op_omap_clear_lat, "op_omap_clear_lat");
+  plb.add_time_avg(l_os_op_omap_setkeys_lat, "op_omap_setkeys_lat");
+  plb.add_time_avg(l_os_op_omap_rmkeys_lat, "op_omap_rmkeys_lat");
+  plb.add_time_avg(l_os_op_omap_rmkeyrange_lat, "op_omap_rmkeyrange_lat");
+  plb.add_time_avg(l_os_op_omap_setheader_lat, "op_omap_setheader_lat");
+  plb.add_time_avg(l_os_op_split_coll_lat, "op_split_coll_lat");
+  plb.add_time_avg(l_os_op_split_coll2_lat, "op_split_coll2_lat");
+
+  plb.add_u64_counter(l_os_rep_do_op, "rep_do_op");
+  plb.add_u64_counter(l_os_rep_append_log, "rep_append_log");

   logger = plb.create_perf_counters();

@@ -1510,8 +1554,8 @@
       goto close_basedir_fd;
     }

-    char dbuf[offsetof(struct dirent, d_name) + PATH_MAX + 1];
     struct dirent *de;
+    char dbuf[offsetof(struct dirent, d_name) + PATH_MAX + 1];
     while (::readdir_r(dir, (struct dirent *)dbuf, &de) == 0) {
       if (!de)
        break;
@@ -1997,6 +2041,8 @@

 void FileStore::_do_op(OpSequencer *osr, ThreadPool::TPHandle &handle)
 {
+  utime_t start = ceph_clock_now(g_ceph_context);
+
   wbthrottle.throttle();
   // inject a stall?
   if (g_conf->filestore_inject_stall) {
@@ -2012,10 +2058,18 @@
   Op *o = osr->peek_queue();
   apply_manager.op_apply_start(o->op);
   dout(5) << "_do_op " << o << " seq " << o->op << " " << *osr << "/" << osr->parent << " start" << dendl;
+
+  utime_t mid = ceph_clock_now(g_ceph_context);
+
   int r = _do_transactions(o->tls, o->op, &handle);
   apply_manager.op_apply_finish(o->op);
   dout(10) << "_do_op " << o << " seq " << o->op << " r = " << r
           << ", finisher " << o->onreadable << " " << o->onreadable_sync << dendl;
+
+  utime_t end = ceph_clock_now(g_ceph_context);
+  logger->tinc(l_os_do_op_lat, end - start );
+  logger->tinc(l_os_do_transactions_lat, end - mid);
+
 }

 void FileStore::_finish_op(OpSequencer *osr)
@@ -2176,7 +2230,14 @@
   for (list<Transaction*>::iterator p = tls.begin();
        p != tls.end();
        ++p, trans_num++) {
+
+    utime_t start = ceph_clock_now(g_ceph_context);
+
     r = _do_transaction(**p, op_seq, trans_num);
+
+    utime_t end = ceph_clock_now(g_ceph_context);
+    logger->tinc(l_os_do_transaction_lat, end - start );
+
     if (r < 0)
       break;
     if (handle)
@@ -2442,10 +2503,33 @@
 {
   dout(10) << "_do_transaction on " << &t << dendl;

+
+  //dout(0) << " transaction dump:" << dendl;
+  //dout(0) << "================================================================ " << dendl;
+  //dout(0) << "\n" ;
+  //JSONFormatter ff(true);
+  //ff.open_object_section("transaction");
+  //t.dump(&ff);
+  //ff.close_section();
+  //ff.flush(*_dout);
+  //*_dout << dendl;
+  //dout(0) << "================================================================ " << dendl;
+
+
+  utime_t start, end;
+  utime_t t1 = ceph_clock_now(g_ceph_context);
+
   Transaction::iterator i = t.begin();

   SequencerPosition spos(op_seq, trans_num, 0);
+
+  utime_t t2 = ceph_clock_now(g_ceph_context);
+
+  logger->tinc(l_os_tran_1_lat, t2 - t1);
+
   while (i.have_op()) {
+    utime_t t3 = ceph_clock_now(g_ceph_context);
+
     int op = i.get_op();
     int r = 0;

@@ -2456,15 +2540,22 @@
       break;
     case Transaction::OP_TOUCH:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        if (_check_replay_guard(cid, oid, spos) > 0)
          r = _touch(cid, oid);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_touch_lat, end - start );
       }
       break;

     case Transaction::OP_WRITE:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        uint64_t off = i.get_length();
@@ -2474,51 +2565,77 @@
        i.get_bl(bl);
        if (_check_replay_guard(cid, oid, spos) > 0)
          r = _write(cid, oid, off, len, bl, replica);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_write_lat, end - start );
+
       }
       break;

     case Transaction::OP_ZERO:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        uint64_t off = i.get_length();
        uint64_t len = i.get_length();
        if (_check_replay_guard(cid, oid, spos) > 0)
          r = _zero(cid, oid, off, len);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_zero_lat, end - start );
       }
       break;

     case Transaction::OP_TRIMCACHE:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        i.get_cid();
        i.get_oid();
        i.get_length();
        i.get_length();
        // deprecated, no-op
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_trimcache_lat, end - start );
       }
       break;

     case Transaction::OP_TRUNCATE:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        uint64_t off = i.get_length();
        if (_check_replay_guard(cid, oid, spos) > 0)
          r = _truncate(cid, oid, off);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_truncate_lat, end - start );
       }
       break;

     case Transaction::OP_REMOVE:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        if (_check_replay_guard(cid, oid, spos) > 0)
          r = _remove(cid, oid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_remove_lat, end - start );
       }
       break;

     case Transaction::OP_SETATTR:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        string name = i.get_attrname();
@@ -2532,11 +2649,16 @@
            dout(0) << " ENOSPC on setxattr on " << cid << "/" << oid
                    << " name " << name << " size " << bl.length() << dendl;
        }
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_setattr_lat, end - start );
       }
       break;

     case Transaction::OP_SETATTRS:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        map<string, bufferptr> aset;
@@ -2545,50 +2667,75 @@
          r = _setattrs(cid, oid, aset, spos);
        if (r == -ENOSPC)
          dout(0) << " ENOSPC on setxattrs on " << cid << "/" << oid << dendl;
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_setattrs_lat, end - start );
       }
       break;

     case Transaction::OP_RMATTR:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        string name = i.get_attrname();
        if (_check_replay_guard(cid, oid, spos) > 0)
          r = _rmattr(cid, oid, name.c_str(), spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_rmattr_lat, end - start );
       }
       break;

     case Transaction::OP_RMATTRS:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        if (_check_replay_guard(cid, oid, spos) > 0)
          r = _rmattrs(cid, oid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_rmattrs_lat, end - start );
       }
       break;

     case Transaction::OP_CLONE:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        hobject_t noid = i.get_oid();
        r = _clone(cid, oid, noid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_clone_lat, end - start );
       }
       break;

     case Transaction::OP_CLONERANGE:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        hobject_t noid = i.get_oid();
        uint64_t off = i.get_length();
        uint64_t len = i.get_length();
        r = _clone_range(cid, oid, noid, off, len, off, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_clonerange_lat, end - start );
       }
       break;

     case Transaction::OP_CLONERANGE2:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        hobject_t noid = i.get_oid();
@@ -2596,45 +2743,70 @@
        uint64_t len = i.get_length();
        uint64_t dstoff = i.get_length();
        r = _clone_range(cid, oid, noid, srcoff, len, dstoff, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_clonerange2_lat, end - start );
       }
       break;

     case Transaction::OP_MKCOLL:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        if (_check_replay_guard(cid, spos) > 0)
          r = _create_collection(cid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_mkcoll_lat, end - start );
       }
       break;

     case Transaction::OP_RMCOLL:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        if (_check_replay_guard(cid, spos) > 0)
          r = _destroy_collection(cid);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_rmcoll_lat, end - start );
       }
       break;

     case Transaction::OP_COLL_ADD:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t ncid = i.get_cid();
        coll_t ocid = i.get_cid();
        hobject_t oid = i.get_oid();
        r = _collection_add(ncid, ocid, oid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_coll_add_lat, end - start );
       }
       break;

     case Transaction::OP_COLL_REMOVE:
        {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        hobject_t oid = i.get_oid();
        if (_check_replay_guard(cid, oid, spos) > 0)
          r = _remove(cid, oid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_coll_remove_lat, end - start );
        }
       break;

     case Transaction::OP_COLL_MOVE:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        // WARNING: this is deprecated and buggy; only here to replay old journals.
        coll_t ocid = i.get_cid();
        coll_t ncid = i.get_cid();
@@ -2643,101 +2815,159 @@
        if (r == 0 &&
            (_check_replay_guard(ocid, oid, spos) > 0))
          r = _remove(ocid, oid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_coll_move_lat, end - start );
       }
       break;

     case Transaction::OP_COLL_SETATTR:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        string name = i.get_attrname();
        bufferlist bl;
        i.get_bl(bl);
        if (_check_replay_guard(cid, spos) > 0)
          r = _collection_setattr(cid, name.c_str(), bl.c_str(), bl.length());
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_coll_setattr_lat, end - start );
       }
       break;

     case Transaction::OP_COLL_RMATTR:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid = i.get_cid();
        string name = i.get_attrname();
        if (_check_replay_guard(cid, spos) > 0)
          r = _collection_rmattr(cid, name.c_str());
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_coll_rmattr_lat, end - start );
       }
       break;

     case Transaction::OP_STARTSYNC:
+      start = ceph_clock_now(g_ceph_context);
+
       _start_sync();
+
+      end = ceph_clock_now(g_ceph_context);
+      logger->tinc(l_os_op_startsync_lat, end - start );
       break;

     case Transaction::OP_COLL_RENAME:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid(i.get_cid());
        coll_t ncid(i.get_cid());
        r = _collection_rename(cid, ncid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_coll_rename_lat, end - start );
       }
       break;

     case Transaction::OP_OMAP_CLEAR:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid(i.get_cid());
        hobject_t oid = i.get_oid();
        r = _omap_clear(cid, oid, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_omap_clear_lat, end - start );
       }
       break;
     case Transaction::OP_OMAP_SETKEYS:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid(i.get_cid());
        hobject_t oid = i.get_oid();
        map<string, bufferlist> aset;
        i.get_attrset(aset);
        r = _omap_setkeys(cid, oid, aset, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_omap_setkeys_lat, end - start );
       }
       break;
     case Transaction::OP_OMAP_RMKEYS:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid(i.get_cid());
        hobject_t oid = i.get_oid();
        set<string> keys;
        i.get_keyset(keys);
        r = _omap_rmkeys(cid, oid, keys, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_omap_rmkeys_lat, end - start );
       }
       break;
     case Transaction::OP_OMAP_RMKEYRANGE:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid(i.get_cid());
        hobject_t oid = i.get_oid();
        string first, last;
        first = i.get_key();
        last = i.get_key();
        r = _omap_rmkeyrange(cid, oid, first, last, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_omap_rmkeyrange_lat, end - start );
       }
       break;
     case Transaction::OP_OMAP_SETHEADER:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid(i.get_cid());
        hobject_t oid = i.get_oid();
        bufferlist bl;
        i.get_bl(bl);
        r = _omap_setheader(cid, oid, bl, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_omap_setheader_lat, end - start );
       }
       break;
     case Transaction::OP_SPLIT_COLLECTION:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid(i.get_cid());
        uint32_t bits(i.get_u32());
        uint32_t rem(i.get_u32());
        coll_t dest(i.get_cid());
        r = _split_collection_create(cid, bits, rem, dest, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_split_coll_lat, end - start );
       }
       break;
     case Transaction::OP_SPLIT_COLLECTION2:
       {
+        start = ceph_clock_now(g_ceph_context);
+
        coll_t cid(i.get_cid());
        uint32_t bits(i.get_u32());
        uint32_t rem(i.get_u32());
        coll_t dest(i.get_cid());
        r = _split_collection(cid, bits, rem, dest, spos);
+
+        end = ceph_clock_now(g_ceph_context);
+        logger->tinc(l_os_op_split_coll2_lat, end - start );
       }
       break;

@@ -2746,6 +2976,9 @@
       assert(0);
     }

+    utime_t t4 = ceph_clock_now(g_ceph_context);
+    logger->tinc(l_os_tran_2_lat, t4 - t3);
+
     if (r < 0) {
       bool ok = false;

@@ -2821,11 +3054,18 @@
       }
     }

+    utime_t t5 = ceph_clock_now(g_ceph_context);
+    logger->tinc(l_os_tran_3_lat, t5 - t4);
+
     spos.op++;
   }

+
   _inject_failure();

+  utime_t t6 = ceph_clock_now(g_ceph_context);
+  logger->tinc(l_os_tran_4_lat, t6 - t2);
+
   return 0;  // FIXME count errors
 }

@@ -3035,9 +3275,15 @@
   int r;

   int64_t actual;
+  utime_t before_write, after_write, before_wb, after_wb, lat;
+  utime_t start, end;

   FDRef fd;
+  start = ceph_clock_now(g_ceph_context);
   r = lfn_open(cid, oid, true, &fd);
+  end = ceph_clock_now(g_ceph_context);
+  logger->tinc(l_os_lfn_open_lat, end - start);
+
   if (r < 0) {
     dout(0) << "write couldn't open " << cid << "/"
            << oid << ": "
@@ -3046,7 +3292,11 @@
   }

   // seek
+  start = ceph_clock_now(g_ceph_context);
   actual = ::lseek64(**fd, offset, SEEK_SET);
+  end = ceph_clock_now(g_ceph_context);
+  logger->tinc(l_os_lseek_lat, end - start);
+
   if (actual < 0) {
     r = -errno;
     dout(0) << "write lseek64 to " << offset << " failed: " << cpp_strerror(r) << dendl;
@@ -3061,14 +3311,26 @@
   }

   // write
+  before_write = ceph_clock_now(g_ceph_context);
+
   r = bl.write_fd(**fd);
   if (r == 0)
     r = bl.length();

+  after_write = ceph_clock_now(g_ceph_context);
+  lat = after_write - before_write;
+  logger->tinc(l_os_writefd_lat, lat);
+
   // flush?
   if (!replaying &&
       g_conf->filestore_wbthrottle_enable)
+  {
+    before_wb = ceph_clock_now(g_ceph_context);
     wbthrottle.queue_wb(fd, oid, offset, len, replica);
+    after_wb = ceph_clock_now(g_ceph_context);
+    lat = after_wb - before_wb;
+    logger->tinc(l_os_wbthrottle_queue_lat, lat);
+  }
   lfn_close(fd);

  out:
@@ -5037,3 +5299,13 @@
   m_filestore_dump_fmt.flush(m_filestore_dump);
   m_filestore_dump.flush();
 }
+
+void FileStore::inc_do_op_counter()
+{
+  logger->inc(l_os_rep_do_op);
+}
+
+void FileStore::inc_append_log_counter()
+{
+  logger->inc(l_os_rep_append_log);
+}
diff -u -r ceph-0.67.3/src/os/FileStore.h ceph-0.67.3-rongze/src/os/FileStore.h
--- ceph-0.67.3/src/os/FileStore.h      2013-09-09 19:47:34.000000000 +0000
+++ ceph-0.67.3-rongze/src/os/FileStore.h       2013-12-17 04:16:41.774440047 +0000
@@ -264,6 +264,9 @@
   int lfn_find(coll_t cid, const hobject_t& oid, IndexedPath *path);
   int lfn_truncate(coll_t cid, const hobject_t& oid, off_t length);
   int lfn_stat(coll_t cid, const hobject_t& oid, struct stat *buf);
+  void inc_do_op_counter();
+  void inc_append_log_counter();
+
   int lfn_open(
     coll_t cid,
     const hobject_t& oid,
diff -u -r ceph-0.67.3/src/os/ObjectStore.h ceph-0.67.3-rongze/src/os/ObjectStore.h
--- ceph-0.67.3/src/os/ObjectStore.h    2013-09-09 19:47:34.000000000 +0000
+++ ceph-0.67.3-rongze/src/os/ObjectStore.h     2013-12-17 04:16:57.481467801 +0000
@@ -68,6 +68,49 @@
   l_os_commit_lat,
   l_os_j_full,
   l_os_queue_lat,
+  l_os_lfn_open_lat,
+  l_os_lseek_lat,
+  l_os_writefd_lat,
+  l_os_wbthrottle_queue_lat,
+  l_os_do_op_lat,
+  l_os_do_transactions_lat,
+  l_os_do_transaction_lat,
+  l_os_write_lat,
+  l_os_tran_1_lat,
+  l_os_tran_2_lat,
+  l_os_tran_3_lat,
+  l_os_tran_4_lat,
+  l_os_op_touch_lat,
+  l_os_op_write_lat,
+  l_os_op_zero_lat,
+  l_os_op_trimcache_lat,
+  l_os_op_truncate_lat,
+  l_os_op_remove_lat,
+  l_os_op_setattr_lat,
+  l_os_op_setattrs_lat,
+  l_os_op_rmattr_lat,
+  l_os_op_rmattrs_lat,
+  l_os_op_clone_lat,
+  l_os_op_clonerange_lat,
+  l_os_op_clonerange2_lat,
+  l_os_op_mkcoll_lat,
+  l_os_op_rmcoll_lat,
+  l_os_op_coll_add_lat,
+  l_os_op_coll_remove_lat,
+  l_os_op_coll_move_lat,
+  l_os_op_coll_setattr_lat,
+  l_os_op_coll_rmattr_lat,
+  l_os_op_startsync_lat,
+  l_os_op_coll_rename_lat,
+  l_os_op_omap_clear_lat,
+  l_os_op_omap_setkeys_lat,
+  l_os_op_omap_rmkeys_lat,
+  l_os_op_omap_rmkeyrange_lat,
+  l_os_op_omap_setheader_lat,
+  l_os_op_split_coll_lat,
+  l_os_op_split_coll2_lat,
+  l_os_rep_do_op,
+  l_os_rep_append_log,
   l_os_last,
 };

@@ -113,7 +156,6 @@
     }
   };

-
   /*********************************
    * transaction
    */
@@ -197,6 +239,7 @@
       register_on_commit(new ContainerContext<RunOnDeleteRef>(_complete));
     }

+
     static void collect_contexts(
       list<Transaction *> &t,
       Context **out_on_applied,
@@ -820,6 +863,8 @@
  public:
   ObjectStore() : logger(NULL) {}
   virtual ~ObjectStore() {}
+  virtual void inc_do_op_counter() {};
+  virtual void inc_append_log_counter() {};

   // mgmt
   virtual int version_stamp_is_valid(uint32_t *version) { return 1; }
@@ -988,6 +1033,7 @@
   // DEBUG
   virtual void inject_data_error(const hobject_t &oid) {}
   virtual void inject_mdata_error(const hobject_t &oid) {}
+
 };


diff -u -r ceph-0.67.3/src/osd/ReplicatedPG.cc ceph-0.67.3-rongze/src/osd/ReplicatedPG.cc
--- ceph-0.67.3/src/osd/ReplicatedPG.cc 2013-09-09 19:47:34.000000000 +0000
+++ ceph-0.67.3-rongze/src/osd/ReplicatedPG.cc  2013-12-17 04:17:22.610512262 +0000
@@ -51,6 +51,7 @@
 #include "json_spirit/json_spirit_reader.h"
 #include "include/assert.h"  // json_spirit clobbers it

+
 #define dout_subsys ceph_subsys_osd
 #define DOUT_PREFIX_ARGS this, osd->whoami, get_osdmap()
 #undef dout_prefix
@@ -641,8 +642,10 @@
     }
     return do_pg_op(op);
   }
+

   dout(10) << "do_op " << *m << (op->may_write() ? " may_write" : "") << dendl;
+  //osd->store->inc_do_op_counter();

   hobject_t head(m->get_oid(), m->get_object_locator().key,
                 CEPH_NOSNAP, m->get_pg().ps(),
@@ -1076,6 +1079,7 @@
   calc_trim_to();

   append_log(ctx->log, pg_trim_to, ctx->local_t);
+  //osd->store->inc_append_log_counter();

   // continuing on to write path, make sure object context is registered
   assert(obc->registered);