From: Sage Weil <sage@inktank.com>
Date: Thu, 28 Feb 2013 23:34:35 +0000 (-0800)
Subject: osd: add 'osd debug op order' to track and assert order of client ops
X-Git-Tag: v0.59~57
X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=2a84437f861be36be21669559e78fecc353e12f0;p=ceph.git

osd: add 'osd debug op order' to track and assert order of client ops

Keep a big fat slow map in memory to ensure that client ops are applied to
objects in the order the clien sent them.  This will make it easier to
catch ordering bugs due to requeuing as soon as they happen, when the logs
are easier to wade through, and not later when the client notices something
is awry.

Signed-off-by: Sage Weil <sage@inktank.com>
Reviewed-by: Samuel Just <sam.just@inktank.com>
---

diff --git a/src/common/config_opts.h b/src/common/config_opts.h
index 278642bab466..2af123dad50d 100644
--- a/src/common/config_opts.h
+++ b/src/common/config_opts.h
@@ -407,6 +407,7 @@ OPTION(osd_debug_drop_ping_duration, OPT_INT, 0)
 OPTION(osd_debug_drop_pg_create_probability, OPT_DOUBLE, 0)
 OPTION(osd_debug_drop_pg_create_duration, OPT_INT, 1)
 OPTION(osd_debug_drop_op_probability, OPT_DOUBLE, 0)   // probability of stalling/dropping a client op
+OPTION(osd_debug_op_order, OPT_BOOL, false)
 OPTION(osd_op_history_size, OPT_U32, 20)    // Max number of completed ops to track
 OPTION(osd_op_history_duration, OPT_U32, 600) // Oldest completed op to track
 OPTION(osd_target_transaction_size, OPT_INT, 30)     // to adjust various transactions that batch smaller items
diff --git a/src/osd/ReplicatedPG.cc b/src/osd/ReplicatedPG.cc
index ecbc5db072c4..34acf24614a1 100644
--- a/src/osd/ReplicatedPG.cc
+++ b/src/osd/ReplicatedPG.cc
@@ -1002,6 +1002,25 @@ void ReplicatedPG::do_op(OpRequestRef op)
   // continuing on to write path, make sure object context is registered
   assert(obc->registered);
 
+  // verify that we are doing this in order?
+  if (g_conf->osd_debug_op_order && m->get_source().is_client()) {
+    map<client_t,tid_t>& cm = debug_op_order[obc->obs.oi.soid];
+    tid_t t = m->get_tid();
+    client_t n = m->get_source().num();
+    map<client_t,tid_t>::iterator p = cm.find(n);
+    if (p == cm.end()) {
+      dout(20) << " op order client." << n << " tid " << t << " (first)" << dendl;
+      cm[n] = t;
+    } else {
+      dout(20) << " op order client." << n << " tid " << t << " last was " << p->second << dendl;
+      if (p->second > t) {
+	derr << "bad op order, already applied " << p->second << " > this " << t << dendl;;
+	assert(0 == "out of order op");
+      }
+      p->second = t;
+    }
+  }
+
   // issue replica writes
   tid_t rep_tid = osd->get_tid();
   RepGather *repop = new_repop(ctx, obc, rep_tid);  // new repop claims our obc, src_obc refs
@@ -6142,6 +6161,8 @@ void ReplicatedPG::on_change()
 
   // clear snap_trimmer state
   snap_trimmer_machine.process_event(Reset());
+
+  debug_op_order.clear();
 }
 
 void ReplicatedPG::on_role_change()
diff --git a/src/osd/ReplicatedPG.h b/src/osd/ReplicatedPG.h
index aac728079bd0..e7fbbfac5ec4 100644
--- a/src/osd/ReplicatedPG.h
+++ b/src/osd/ReplicatedPG.h
@@ -433,6 +433,9 @@ protected:
   map<hobject_t, ObjectContext*> object_contexts;
   map<object_t, SnapSetContext*> snapset_contexts;
 
+  // debug order that client ops are applied
+  map<hobject_t, map<client_t, tid_t> > debug_op_order;
+
   void populate_obc_watchers(ObjectContext *obc);
 public:
   void handle_watch_timeout(WatchRef watch);