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 278642bab466b3a39340692c6b7d3123dc6b5d2f..2af123dad50dcfe8513bcf8e6f132300484e571d 100644 (file)
--- 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 ecbc5db072c44f68cef27639a69c0607cb5b829a..34acf24614a1bf6ccf58c98436132c9c5182622e 100644 (file)
--- 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 aac728079bd09091c8acef9f809bcebafbff2b34..e7fbbfac5ec4b08efa812408ced9340b5947e2b4 100644 (file)
--- 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);