test: Add optional timestamps to ceph_test_rados

With this commit, if the --timestamps parameter is passed to
ceph_test_rados, most output lines are prefixed with a timestamp.

If not specified, the output should be identical to before.

This is useful for correlating what the test is doing with  ceph
osd logs.

Signed-off-by: Alex Ainscow <aainscow@uk.ibm.com>

diff --git a/src/test/osd/RadosModel.h b/src/test/osd/RadosModel.h
index 703ce70465164ce52f7e5587d7b8f711af8efa12..55f8b7d360362d065ab0a6bcb39ac244095032d9 100644 (file)
--- a/src/test/osd/RadosModel.h
+++ b/src/test/osd/RadosModel.h
@@ -201,6 +201,7 @@ public:
   bool enable_dedup;
   std::string chunk_algo;
   std::string chunk_size;
+  bool timestamp;
 
   RadosTestContext(const std::string &pool_name,
                   int max_in_flight,
@@ -213,6 +214,7 @@ public:
                   bool write_fadvise_dontneed,
                   const std::string &low_tier_pool_name,
                   bool enable_dedup,
+                  bool timestamp,
                   std::string chunk_algo,
                   std::string chunk_size,
                   size_t max_attr_len,
@@ -236,7 +238,8 @@ public:
     snapname_num(0),
     enable_dedup(enable_dedup),
     chunk_algo(chunk_algo),
-    chunk_size(chunk_size)
+    chunk_size(chunk_size),
+    timestamp(timestamp)
   {
   }
 
@@ -353,7 +356,7 @@ public:
        for (auto i = inflight.begin();
             i != inflight.end();) {
          if ((*i)->finished()) {
-           std::cout << (*i)->num << ": done (" << (inflight.size()-1) << " left)" << std::endl;
+           cout_prefix() << (*i)->num << ": done (" << (inflight.size()-1) << " left)" << std::endl;
            delete *i;
            inflight.erase(i++);
          } else {
@@ -362,7 +365,7 @@ public:
        }
 
        if (inflight.size() >= (unsigned) max_in_flight || (!next && !inflight.empty())) {
-         std::cout << " waiting on " << inflight.size() << std::endl;
+         cout_prefix() << " waiting on " << inflight.size() << std::endl;
          wait_cond.wait(state_locker);
        } else {
          break;
@@ -495,7 +498,7 @@ public:
       if (j != i->second.end()) {
        if (version)
          j->second.version = version;
-       std::cout << __func__ << " oid " << oid
+       cout_prefix() << __func__ << " oid " << oid
                  << " v " << version << " " << j->second.most_recent()
                  << " " << (j->second.dirty ? "dirty" : "clean")
                  << " " << (j->second.exists ? "exists" : "dne")
@@ -612,7 +615,7 @@ public:
        continue;
       std::map<std::string,ObjectDesc>::iterator j = i->second.find(oid);
       if (j != i->second.end() && !j->second.flushed) {
-       std::cout << __func__ << " oid " << oid
+       cout_prefix() << __func__ << " oid " << oid
                  << " v " << j->second.version << " " << j->second.most_recent()
                  << " " << (j->second.flushed ? "flushed" : "unflushed")
                  << " " << i->first << std::endl;
@@ -704,11 +707,28 @@ public:
     bool has_snap = false;
     if (snap_set.clones.size()) {
       has_snap = true;
-      std::cout << __func__ << " has snap true " << std::endl;
+      cout_prefix() << __func__ << " has snap true " << std::endl;
     }
     io_ctx.snap_set_read(0);
     return has_snap;
   }
+ public:
+  std::string timestamp_string() {
+    if (timestamp) {
+      ceph::logging::log_clock clock;
+      clock.coarsen();
+      auto t = clock.now();
+      constexpr int buflen = 128;
+      char buf[buflen];
+      ceph::logging::append_time(t, buf, buflen);
+      return std::string(buf) + " ";
+    }
+    return std::string();
+  }
+
+  std::ostream &cout_prefix() {
+    return std::cout << timestamp_string();
+  }
 };
 
 void read_callback(librados::completion_t comp, void *arg);
@@ -977,7 +997,7 @@ public:
     std::map<uint64_t, uint64_t> ranges;
 
     cont_gen->get_ranges_map(cont, ranges);
-    std::cout << num << ":  seq_num " << context->seq_num << " ranges " << ranges << std::endl;
+    context->cout_prefix() << num << ":  seq_num " << context->seq_num << " ranges " << ranges << std::endl;
     context->seq_num++;
 
     waiting_on = ranges.size();
@@ -989,7 +1009,7 @@ public:
       bufferlist to_write = gen_pos.gen_bl_advance(len);
       ceph_assert(to_write.length() == len);
       ceph_assert(to_write.length() > 0);
-      std::cout << num << ":  writing " << context->prefix+oid
+      context->cout_prefix() << num << ":  writing " << context->prefix+oid
                << " from " << offset
                << " to " << len + offset << " tid " << tid << std::endl;
       auto cb_arg =
@@ -1049,7 +1069,7 @@ public:
     std::lock_guard state_locker{context->state_lock};
     uint64_t tid = info->id;
 
-    std::cout << num << ":  finishing write tid " << tid << " to " << context->prefix + oid << std::endl;
+    context->cout_prefix() << num << ":  finishing write tid " << tid << " to " << context->prefix + oid << std::endl;
 
     if (tid <= last_acked_tid) {
       std::cerr << "Error: finished tid " << tid
@@ -1070,11 +1090,11 @@ public:
           ceph_abort();
        }
        if ((*i)->get_version64() > version) {
-          std::cout << num << ":  oid " << oid << " updating version " << version
+          context->cout_prefix() << num << ":  oid " << oid << " updating version " << version
                     << " to " << (*i)->get_version64() << std::endl;
          version = (*i)->get_version64();
         } else {
-          std::cout << num << ":  oid " << oid << " version " << version
+          context->cout_prefix() << num << ":  oid " << oid << " version " << version
                     << " is already newer than " << (*i)->get_version64() << std::endl;
         }
        (*i)->release();
@@ -1097,9 +1117,9 @@ public:
        ObjectDesc old_value;
        ceph_assert(context->find_object(oid, &old_value, -1));
        if (old_value.deleted())
-         std::cout << num << ":  left oid " << oid << " deleted" << std::endl;
+         context->cout_prefix() << num << ":  left oid " << oid << " deleted" << std::endl;
        else
-         std::cout << num << ":  left oid " << oid << " "
+         context->cout_prefix() << num << ":  left oid " << oid << " "
                    << old_value.most_recent() << std::endl;
       }
 
@@ -1164,7 +1184,7 @@ public:
     std::map<uint64_t, uint64_t> ranges;
 
     cont_gen->get_ranges_map(cont, ranges);
-    std::cout << num << ":  seq_num " << context->seq_num << " ranges " << ranges << std::endl;
+    context->cout_prefix() << num << ":  seq_num " << context->seq_num << " ranges " << ranges << std::endl;
     context->seq_num++;
 
     waiting_on = ranges.size();
@@ -1176,7 +1196,7 @@ public:
       bufferlist to_write = gen_pos.gen_bl_advance(len);
       ceph_assert(to_write.length() == len);
       ceph_assert(to_write.length() > 0);
-      std::cout << num << ":  writing " << context->prefix+oid
+      context->cout_prefix() << num << ":  writing " << context->prefix+oid
                << " from " << offset
                << " to " << offset + len << " tid " << tid << std::endl;
       auto cb_arg =
@@ -1231,7 +1251,7 @@ public:
     std::lock_guard state_locker{context->state_lock};
     uint64_t tid = info->id;
 
-    std::cout << num << ":  finishing writesame tid " << tid << " to " << context->prefix + oid << std::endl;
+    context->cout_prefix() << num << ":  finishing writesame tid " << tid << " to " << context->prefix + oid << std::endl;
 
     if (tid <= last_acked_tid) {
       std::cerr << "Error: finished tid " << tid
@@ -1252,11 +1272,11 @@ public:
           ceph_abort();
        }
        if ((*i)->get_version64() > version) {
-          std::cout << "oid " << oid << "updating version " << version
+          context->cout_prefix() << "oid " << oid << "updating version " << version
                     << "to " << (*i)->get_version64() << std::endl;
          version = (*i)->get_version64();
         } else {
-          std::cout << "oid " << oid << "version " << version
+          context->cout_prefix() << "oid " << oid << "version " << version
                     << "is already newer than " << (*i)->get_version64() << std::endl;
         }
        (*i)->release();
@@ -1279,9 +1299,9 @@ public:
        ObjectDesc old_value;
        ceph_assert(context->find_object(oid, &old_value, -1));
        if (old_value.deleted())
-         std::cout << num << ":  left oid " << oid << " deleted" << std::endl;
+         context->cout_prefix() << num << ":  left oid " << oid << " deleted" << std::endl;
        else
-         std::cout << num << ":  left oid " << oid << " "
+         context->cout_prefix() << num << ":  left oid " << oid << " "
                    << old_value.most_recent() << std::endl;
       }
 
@@ -1473,7 +1493,7 @@ public:
     } else {
       snap = -1;
     }
-    std::cout << num << ": read oid " << oid << " snap " << snap << std::endl;
+    context->cout_prefix() << num << ": read oid " << oid << " snap " << snap << std::endl;
     done = 0;
     for (uint32_t i = 0; i < 3; i++) {
       completions[i] = context->rados.aio_create_completion((void *) this, &read_callback);
@@ -1483,9 +1503,9 @@ public:
     context->oid_not_in_use.erase(oid);
     ceph_assert(context->find_object(oid, &old_value, snap));
     if (old_value.deleted())
-      std::cout << num << ":  expect deleted" << std::endl;
+      context->cout_prefix() << num << ":  expect deleted" << std::endl;
     else
-      std::cout << num << ":  expect " << old_value.most_recent() << std::endl;
+      context->cout_prefix() << num << ":  expect " << old_value.most_recent() << std::endl;
 
     TestWatchContext *ctx = context->get_watch_context(oid);
     state_locker.unlock();
@@ -1601,10 +1621,10 @@ public:
        xattrs.erase(iter);
       }
       if (old_value.deleted()) {
-       std::cout << num << ":  expect deleted" << std::endl;
+       context->cout_prefix() << num << ":  expect deleted" << std::endl;
        ceph_abort_msg("expected deleted");
       } else {
-       std::cout << num << ":  expect " << old_value.most_recent() << std::endl;
+       context->cout_prefix() << num << ":  expect " << old_value.most_recent() << std::endl;
       }
       if (old_value.has_contents()) {
        ContDesc to_check;
@@ -1950,7 +1970,7 @@ public:
       roll_back_to);
 
 
-    std::cout << "rollback oid " << oid << " to " << roll_back_to << std::endl;
+    context->cout_prefix() << "rollback oid " << oid << " to " << roll_back_to << std::endl;
 
     bool existed_before = context->object_existed_at(oid);
     bool existed_after = context->object_existed_at(oid, roll_back_to);
@@ -2008,7 +2028,7 @@ public:
   {
     std::lock_guard l{context->state_lock};
     uint64_t tid = info->id;
-    std::cout << num << ":  finishing rollback tid " << tid
+    context->cout_prefix() << num << ":  finishing rollback tid " << tid
         << " to " << context->prefix + oid << std::endl;
     ceph_assert((int)(info->id) > last_finished);
     last_finished = info->id;
@@ -2120,10 +2140,10 @@ public:
     if (info->id == 0) {
       // copy_from
       ceph_assert(comp->is_complete());
-      std::cout << num << ":  finishing copy_from to " << context->prefix + oid << std::endl;
+      context->cout_prefix() << num << ":  finishing copy_from to " << context->prefix + oid << std::endl;
       if ((r = comp->get_return_value())) {
        if (r == -ENOENT && src_value.deleted()) {
-         std::cout << num << ":  got expected ENOENT (src dne)" << std::endl;
+         context->cout_prefix() << num << ":  got expected ENOENT (src dne)" << std::endl;
        } else {
          std::cerr << "Error: oid " << oid << " copy_from " << oid_src << " returned error code "
               << r << std::endl;
@@ -2137,7 +2157,7 @@ public:
     } else if (info->id == 1) {
       // racing read
       ceph_assert(comp_racing_read->is_complete());
-      std::cout << num << ":  finishing copy_from racing read to " << context->prefix + oid << std::endl;
+      context->cout_prefix() << num << ":  finishing copy_from racing read to " << context->prefix + oid << std::endl;
       if ((r = comp_racing_read->get_return_value())) {
        if (!(r == -ENOENT && src_value.deleted())) {
          std::cerr << "Error: oid " << oid << " copy_from " << oid_src << " returned error code "
@@ -2217,7 +2237,7 @@ public:
   {}
 
   void _do_read(librados::ObjectReadOperation& read_op, uint32_t offset, uint32_t length, int index) {
-    std::cout << __func__ << ":" << __LINE__ << std::endl;
+    context->cout_prefix() << __func__ << ":" << __LINE__ << std::endl;
     read_op.read(offset,
                 length,
                 &results[index],
@@ -2234,7 +2254,7 @@ public:
   void _begin() override
   {
     context->state_lock.lock();
-    std::cout << num << ": chunk read oid " << oid << " snap " << snap << std::endl;
+    context->cout_prefix() << num << ": chunk read oid " << oid << " snap " << snap << std::endl;
     done = 0;
     for (uint32_t i = 0; i < 2; i++) {
       completions[i] = context->rados.aio_create_completion((void *) this, &read_callback);
@@ -2243,7 +2263,7 @@ public:
     context->find_object(oid, &old_value);
 
     if (old_value.chunk_info.size() == 0) {
-      std::cout << ":  no chunks" << std::endl;
+      context->cout_prefix() << ":  no chunks" << std::endl;
       context->kick();
       context->state_lock.unlock();
       done = true;
@@ -2253,9 +2273,9 @@ public:
     context->oid_in_use.insert(oid);
     context->oid_not_in_use.erase(oid);
     if (old_value.deleted()) {
-      std::cout << num << ":  expect deleted" << std::endl;
+      context->cout_prefix() << num << ":  expect deleted" << std::endl;
     } else {
-      std::cout << num << ":  expect " << old_value.most_recent() << std::endl;
+      context->cout_prefix() << num << ":  expect " << old_value.most_recent() << std::endl;
     }
 
     int rand_index = rand() % old_value.chunk_info.size();
@@ -2273,7 +2293,7 @@ public:
     tgt_offset = iter->second.offset + offset - iter->first;
     tgt_oid = iter->second.oid;
 
-    std::cout << num << ": ori offset " << iter->first << " req offset " << offset 
+    context->cout_prefix() << num << ": ori offset " << iter->first << " req offset " << offset
              << " ori length " << iter->second.length << " req length " << length
              << " ori tgt_offset " << iter->second.offset << " req tgt_offset " << tgt_offset 
              << " tgt_oid " << tgt_oid << std::endl;
@@ -2329,7 +2349,7 @@ public:
     context->oid_in_use.erase(oid);
     context->oid_not_in_use.insert(oid);
     int retval = completions[0]->get_return_value();
-    std::cout << ":  finish!! ret: " << retval << std::endl;
+    context->cout_prefix() << ":  finish!! ret: " << retval << std::endl;
     context->find_object(tgt_oid, &tgt_value);
 
     for (int i = 0; i < 2; i++) {
@@ -2351,10 +2371,10 @@ public:
 
     if (!retval) {
       if (old_value.deleted()) {
-       std::cout << num << ":  expect deleted" << std::endl;
+       context->cout_prefix() << num << ":  expect deleted" << std::endl;
        ceph_abort_msg("expected deleted");
       } else {
-       std::cout << num << ":  expect " << old_value.most_recent() << std::endl;
+       context->cout_prefix() << num << ":  expect " << old_value.most_recent() << std::endl;
       }
       if (tgt_value.has_contents()) {
        uint32_t checksum[2] = {0};
@@ -2435,7 +2455,7 @@ public:
     context->find_object(oid_src, &src_value); 
     op.copy_from(src.c_str(), context->io_ctx, src_value.version, 0);
 
-    std::cout << "copy op oid " << oid_src << " to " << oid << " tgt_pool_name " << tgt_pool_name <<  std::endl;
+    context->cout_prefix() << "copy op oid " << oid_src << " to " << oid << " tgt_pool_name " << tgt_pool_name <<  std::endl;
 
     std::pair<TestOp*, TestOp::CallbackInfo*> *cb_arg =
       new std::pair<TestOp*, TestOp::CallbackInfo*>(this,
@@ -2454,7 +2474,7 @@ public:
 
     if (info->id == 0) {
       ceph_assert(comp->is_complete());
-      std::cout << num << ":  finishing copy op to oid " << oid << std::endl;
+      context->cout_prefix() << num << ":  finishing copy op to oid " << oid << std::endl;
       if ((r = comp->get_return_value())) {
        std::cerr << "Error: oid " << oid << " write returned error code "
                  << r << std::endl;
@@ -2573,7 +2593,7 @@ public:
       target_oid = context->prefix+oid_tgt;
     }
 
-    std::cout << num << ": " << "set_chunk oid " << oid << " offset: " << offset
+    context->cout_prefix() << num << ": " << "set_chunk oid " << oid << " offset: " << offset
          << " length: " << length <<  " target oid " << target_oid
          << " offset: " << tgt_offset << " snap " << snap << std::endl;
 
@@ -2598,17 +2618,17 @@ public:
 
     if (info->id == 0) {
       ceph_assert(comp->is_complete());
-      std::cout << num << ":  finishing set_chunk to oid " << oid << std::endl;
+      context->cout_prefix() << num << ":  finishing set_chunk to oid " << oid << std::endl;
       if ((r = comp->get_return_value())) {
        if (r == -ENOENT && src_value.deleted()) {
-         std::cout << num << ":  got expected ENOENT (src dne)" << std::endl;
+         context->cout_prefix() << num << ":  got expected ENOENT (src dne)" << std::endl;
        } else if (r == -ENOENT && context->oid_set_chunk_tgt_pool.find(oid_tgt) != 
                  context->oid_set_chunk_tgt_pool.end()) {
-         std::cout << num << ": get expected ENOENT tgt oid " << oid_tgt << std::endl;
+         context->cout_prefix() << num << ": get expected ENOENT tgt oid " << oid_tgt << std::endl;
        } else if (r == -ERANGE && src_value.deleted()) {
-         std::cout << num << ":  got expected ERANGE (src dne)" << std::endl;
+         context->cout_prefix() << num << ":  got expected ERANGE (src dne)" << std::endl;
        } else if (r == -EOPNOTSUPP) {
-         std::cout << "Range is overlapped: oid " << oid << " set_chunk " << oid_tgt << " returned error code "
+         context->cout_prefix() << "Range is overlapped: oid " << oid << " set_chunk " << oid_tgt << " returned error code "
                << r << " offset: " << offset << " length: " << length <<  std::endl;
          context->update_object_version(oid, comp->get_version64());
        } else {
@@ -2763,10 +2783,10 @@ public:
 
     if (info->id == 0) {
       ceph_assert(comp->is_complete());
-      std::cout << num << ":  finishing set_redirect to oid " << oid << std::endl;
+      context->cout_prefix() << num << ":  finishing set_redirect to oid " << oid << std::endl;
       if ((r = comp->get_return_value())) {
        if (r == -ENOENT && src_value.deleted()) {
-         std::cout << num << ":  got expected ENOENT (src dne)" << std::endl;
+         context->cout_prefix() << num << ":  got expected ENOENT (src dne)" << std::endl;
        } else {
          std::cerr << "Error: oid " << oid << " set_redirect " << oid_tgt << " returned error code "
               << r << std::endl;
@@ -2905,11 +2925,11 @@ public:
     ObjectDesc oid_value;
     context->find_object(oid, &oid_value);
     int r = completion->get_return_value();
-    std::cout << num << ":  got " << cpp_strerror(r) << std::endl;
+    context->cout_prefix() << num << ":  got " << cpp_strerror(r) << std::endl;
     if (r == 0) {
       // sucess
     } else if (r == -ENOENT && src_value.deleted()) {
-      std::cout << num << ":  got expected ENOENT (src dne)" << std::endl;
+      context->cout_prefix() << num << ":  got expected ENOENT (src dne)" << std::endl;
     } else {
       ceph_abort_msg("shouldn't happen");
     }
@@ -2966,7 +2986,7 @@ public:
       snap = -1;
     }
 
-    std::cout << num << ": tier_flush oid " << oid << " snap " << snap << std::endl;
+    context->cout_prefix() << num << ": tier_flush oid " << oid << " snap " << snap << std::endl;
 
     if (snap >= 0) {
       context->io_ctx.snap_set_read(context->snaps[snap]);
@@ -2999,7 +3019,7 @@ public:
     ceph_assert(completion->is_complete());
 
     int r = completion->get_return_value();
-    std::cout << num << ":  got " << cpp_strerror(r) << std::endl;
+    context->cout_prefix() << num << ":  got " << cpp_strerror(r) << std::endl;
 
     if (r == 0) {
       // sucess
@@ -3011,10 +3031,10 @@ public:
     } else if (r == -ENOENT) {
       // could fail if object is removed
       if (src_value.deleted()) {
-       std::cout << num << ":  got expected ENOENT (src dne)" << std::endl;
+       context->cout_prefix() << num << ":  got expected ENOENT (src dne)" << std::endl;
       } else {
        if (context->has_snapshot(oid)) {
-         std::cout << num << ":  got expected ENOENT \
+         context->cout_prefix() << num << ":  got expected ENOENT \
            -- adjacent snapshot might not be recovered yet" << std::endl;
        } else {
          std::cerr << num << ": got unexpected ENOENT" << std::endl;
@@ -3078,7 +3098,7 @@ public:
       snap = -1;
     }
 
-    std::cout << num << ": tier_evict oid " << oid << " snap " << snap << std::endl;
+    context->cout_prefix() << num << ": tier_evict oid " << oid << " snap " << snap << std::endl;
 
     if (snap >= 0) {
       context->io_ctx.snap_set_read(context->snaps[snap]);
@@ -3111,7 +3131,7 @@ public:
     ceph_assert(completion->is_complete());
 
     int r = completion->get_return_value();
-    std::cout << num << ":  got " << cpp_strerror(r) << std::endl;
+    context->cout_prefix() << num << ":  got " << cpp_strerror(r) << std::endl;
     if (r == 0) {
       // ok
     } else if (r == -EINVAL) {
@@ -3121,7 +3141,7 @@ public:
     } else if (r == -ENOENT) {
       // could fail if object is removed
       if (src_value.deleted()) {
-       std::cout << num << ":  got expected ENOENT (src dne)" << std::endl;
+       context->cout_prefix() << num << ":  got expected ENOENT (src dne)" << std::endl;
       } else {
        std::cerr << num << ": got unexpected ENOENT" << std::endl;
        ceph_abort();
@@ -3200,7 +3220,7 @@ public:
        HitSet hitset;
        auto p = bl.cbegin();
        decode(hitset, p);
-       std::cout << num << ": got hitset of type " << hitset.get_type_name()
+       context->cout_prefix() << num << ": got hitset of type " << hitset.get_type_name()
                  << " size " << bl.length()
                  << std::endl;
       } else {
@@ -3310,7 +3330,7 @@ public:
     } else {
       snap = -1;
     }
-    std::cout << num << ": is_dirty oid " << oid << " snap " << snap
+    context->cout_prefix() << num << ": is_dirty oid " << oid << " snap " << snap
              << std::endl;
 
     std::pair<TestOp*, TestOp::CallbackInfo*> *cb_arg =
@@ -3349,11 +3369,11 @@ public:
 
     int r = completion->get_return_value();
     if (r == 0) {
-      std::cout << num << ":  " << (dirty ? "dirty" : "clean") << std::endl;
+      context->cout_prefix() << num << ":  " << (dirty ? "dirty" : "clean") << std::endl;
       ceph_assert(!old_value.deleted());
       ceph_assert(dirty == old_value.dirty);
     } else {
-      std::cout << num << ":  got " << r << std::endl;
+      context->cout_prefix() << num << ":  got " << r << std::endl;
       ceph_assert(r == -ENOENT);
       ceph_assert(old_value.deleted());
     }
@@ -3413,7 +3433,7 @@ public:
     // FIXME: we could fail if we've ever removed a snap due to
     // the async snap trimming.
     can_fail = true;
-    std::cout << num << ": " << (blocking ? "cache_flush" : "cache_try_flush")
+    context->cout_prefix() << num << ": " << (blocking ? "cache_flush" : "cache_try_flush")
         << " oid " << oid << " snap " << snap << std::endl;
 
     if (snap >= 0) {
@@ -3453,7 +3473,7 @@ public:
     context->oid_flushing.erase(oid);
     context->oid_not_flushing.insert(oid);
     int r = completion->get_return_value();
-    std::cout << num << ":  got " << cpp_strerror(r) << std::endl;
+    context->cout_prefix() << num << ":  got " << cpp_strerror(r) << std::endl;
     if (r == 0) {
       context->update_object_version(oid, 0, snap);
     } else if (r == -EBUSY) {
@@ -3507,7 +3527,7 @@ public:
     } else {
       snap = -1;
     }
-    std::cout << num << ": cache_evict oid " << oid << " snap " << snap << std::endl;
+    context->cout_prefix() << num << ": cache_evict oid " << oid << " snap " << snap << std::endl;
 
     if (snap >= 0) {
       context->io_ctx.snap_set_read(context->snaps[snap]);
@@ -3538,7 +3558,7 @@ public:
     ceph_assert(completion->is_complete());
 
     int r = completion->get_return_value();
-    std::cout << num << ":  got " << cpp_strerror(r) << std::endl;
+    context->cout_prefix() << num << ":  got " << cpp_strerror(r) << std::endl;
     if (r == 0) {
       // yay!
     } else if (r == -EBUSY) {

diff --git a/src/test/osd/TestRados.cc b/src/test/osd/TestRados.cc
index f0acb24a3de7b86fa7a058ab3e8be6d269b9294b..255b53a3716e91ce6b90ac6158b161d4f1de9c37 100644 (file)
--- a/src/test/osd/TestRados.cc
+++ b/src/test/osd/TestRados.cc
@@ -32,7 +32,8 @@ public:
                        uint8_t offlen_randomization_ratio,
                        bool set_redirect,
                        bool set_chunk,
-                       bool enable_dedup) :
+                       bool enable_dedup,
+                       RadosTestContext *context) :
     m_nextop(NULL), m_op(0), m_ops(ops), m_seconds(max_seconds),
     m_objects(objects), m_stats(stats),
     m_total_weight(0),
@@ -42,7 +43,8 @@ public:
     m_offlen_randomization_ratio(offlen_randomization_ratio),
     m_set_redirect(set_redirect),
     m_set_chunk(set_chunk),
-    m_enable_dedup(enable_dedup)
+    m_enable_dedup(enable_dedup),
+    context(context)
   {
     m_start = time(0);
     for (map<TestOpType, unsigned int>::const_iterator it = op_weights.begin();
@@ -74,7 +76,7 @@ public:
        // make it a long name
        oid << " " << string(300, 'o');
        }*/
-      cout << m_op << ": write initial oid " << oid.str() << std::endl;
+      context.cout_prefix() << m_op << ": write initial oid " << oid.str() << std::endl;
       context.oid_not_flushing.insert(oid.str());
       if (m_ec_pool) {
        return new WriteOp(m_op, &context, oid.str(), true, true);
@@ -145,7 +147,7 @@ public:
       /*if (m_op % 2) {
        oid << " " << string(300, 'o');
        }*/
-      cout << m_op << ": write initial oid " << oid.str() << std::endl;
+      context.cout_prefix() << m_op << ": write initial oid " << oid.str() << std::endl;
       context.oid_not_flushing.insert(oid.str());
       if (m_ec_pool) {
        op = new WriteOp(m_op, &context, oid.str(), true, true);
@@ -166,7 +168,7 @@ public:
           /* previous write is not finished */
           op = NULL;
           m_op--;
-          cout << m_op << " wait for completion of write op! " << std::endl;
+          context.cout_prefix() << m_op << " wait for completion of write op! " << std::endl;
           return true;
         }
 
@@ -178,7 +180,7 @@ public:
        if ((_oid2) % 2) {
          oid2 << " " << string(300, 'm');
        }
-       cout << m_op << ": " << "copy oid " << oid.str() << " target oid " 
+       context.cout_prefix() << m_op << ": " << "copy oid " << oid.str() << " target oid "
              << oid2.str() << std::endl;
        op = new CopyOp(m_op, &context, oid.str(), oid2.str(), context.low_tier_pool_name);
        return true;
@@ -198,10 +200,10 @@ public:
          /* previous copy is not finished */
          op = NULL;
          m_op--;
-         cout << m_op << " retry set_redirect !" << std::endl;
+         context.cout_prefix() << m_op << " retry set_redirect !" << std::endl;
          return true;
        }
-       cout << m_op << ": " << "set_redirect oid " << oid.str() << " target oid " 
+       context.cout_prefix() << m_op << ": " << "set_redirect oid " << oid.str() << " target oid "
              << oid2.str() << std::endl;
        op = new SetRedirectOp(m_op, &context, oid.str(), oid2.str(), context.pool_name);
        return true;
@@ -216,7 +218,7 @@ public:
          /* previous set-chunk is not finished */
          op = NULL;
          m_op--;
-         cout << m_op << " retry set_chunk !" << std::endl;
+         context.cout_prefix() << m_op << " retry set_chunk !" << std::endl;
          return true;
        }
        stringstream oid2;
@@ -225,7 +227,7 @@ public:
          oid2 << " " << string(300, 'm');
        }
 
-       cout << m_op << ": " << "set_chunk oid " << oid.str() 
+       context.cout_prefix() << m_op << ": " << "set_chunk oid " << oid.str()
             <<  " target oid " << oid2.str()  << std::endl;
        op = new SetChunkOp(m_op, &context, oid.str(), oid2.str(), m_stats);
        return true;
@@ -233,12 +235,12 @@ public:
     } else if (m_op == make_manifest_end + 1) {
       int set_size = context.oid_not_in_use.size();
       int set_manifest_size = context.oid_redirect_not_in_use.size();
-      cout << m_op << " oid_not_in_use " << set_size << " oid_redirect_not_in_use " << set_manifest_size <<  std::endl;
+      context.cout_prefix() << m_op << " oid_not_in_use " << set_size << " oid_redirect_not_in_use " << set_manifest_size <<  std::endl;
       /* wait for redirect or set_chunk initialization */
       if (set_size != m_objects || set_manifest_size != 0) {
        op = NULL;
        m_op--;
-       cout << m_op << " wait for manifest initialization " << std::endl;
+       context.cout_prefix() << m_op << " wait for manifest initialization " << std::endl;
        return true;
       }
       for (int t_op = m_objects+1; t_op <= m_objects*2; t_op++) {
@@ -247,7 +249,7 @@ public:
        if (t_op % 2) {
          oid << " " << string(300, 'm');
        }
-       cout << " redirect_not_in_use: " << oid.str() << std::endl;
+       context.cout_prefix() << " redirect_not_in_use: " << oid.str() << std::endl;
        context.oid_redirect_not_in_use.insert(oid.str());
       }
     } 
@@ -270,32 +272,32 @@ private:
 
     case TEST_OP_WRITE:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "write oid " << oid << " current snap is "
+      context.cout_prefix() << m_op << ": " << "write oid " << oid << " current snap is "
           << context.current_snap << std::endl;
       return new WriteOp(m_op, &context, oid, false, false, m_stats);
 
     case TEST_OP_WRITE_EXCL:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "write (excl) oid "
+      context.cout_prefix() << m_op << ": " << "write (excl) oid "
           << oid << " current snap is "
           << context.current_snap << std::endl;
       return new WriteOp(m_op, &context, oid, false, true, m_stats);
 
     case TEST_OP_WRITESAME:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "writesame oid "
+      context.cout_prefix() << m_op << ": " << "writesame oid "
           << oid << " current snap is "
           << context.current_snap << std::endl;
       return new WriteSameOp(m_op, &context, oid, m_stats);
 
     case TEST_OP_DELETE:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "delete oid " << oid << " current snap is "
+      context.cout_prefix() << m_op << ": " << "delete oid " << oid << " current snap is "
           << context.current_snap << std::endl;
       return new DeleteOp(m_op, &context, oid, m_stats);
 
     case TEST_OP_SNAP_CREATE:
-      cout << m_op << ": " << "snap_create" << std::endl;
+      context.cout_prefix() << m_op << ": " << "snap_create" << std::endl;
       return new SnapCreateOp(m_op, &context, m_stats);
 
     case TEST_OP_SNAP_REMOVE:
@@ -306,33 +308,33 @@ private:
        int snap = rand_choose(context.snaps)->first;
        if (context.snaps_in_use.lookup(snap))
          continue;  // in use; try again!
-       cout << m_op << ": " << "snap_remove snap " << snap << std::endl;
+       context.cout_prefix() << m_op << ": " << "snap_remove snap " << snap << std::endl;
        return new SnapRemoveOp(m_op, &context, snap, m_stats);
       }
 
     case TEST_OP_ROLLBACK:
       {
        string oid = *(rand_choose(context.oid_not_in_use));
-       cout << m_op << ": " << "rollback oid " << oid << " current snap is "
+       context.cout_prefix() << m_op << ": " << "rollback oid " << oid << " current snap is "
             << context.current_snap << std::endl;
        return new RollbackOp(m_op, &context, oid);
       }
 
     case TEST_OP_SETATTR:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "setattr oid " << oid
+      context.cout_prefix() << m_op << ": " << "setattr oid " << oid
           << " current snap is " << context.current_snap << std::endl;
       return new SetAttrsOp(m_op, &context, oid, m_stats);
 
     case TEST_OP_RMATTR:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "rmattr oid " << oid
+      context.cout_prefix() << m_op << ": " << "rmattr oid " << oid
           << " current snap is " << context.current_snap << std::endl;
       return new RemoveAttrsOp(m_op, &context, oid, m_stats);
 
     case TEST_OP_WATCH:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "watch oid " << oid
+      context.cout_prefix() << m_op << ": " << "watch oid " << oid
           << " current snap is " << context.current_snap << std::endl;
       return new WatchOp(m_op, &context, oid, m_stats);
 
@@ -341,21 +343,21 @@ private:
       do {
        oid2 = *(rand_choose(context.oid_not_in_use));
       } while (oid == oid2);
-      cout << m_op << ": " << "copy_from oid " << oid << " from oid " << oid2
+      context.cout_prefix() << m_op << ": " << "copy_from oid " << oid << " from oid " << oid2
           << " current snap is " << context.current_snap << std::endl;
       return new CopyFromOp(m_op, &context, oid, oid2, m_stats);
 
     case TEST_OP_HIT_SET_LIST:
       {
        uint32_t hash = rjhash32(rand());
-       cout << m_op << ": " << "hit_set_list " << hash << std::endl;
+       context.cout_prefix() << m_op << ": " << "hit_set_list " << hash << std::endl;
        return new HitSetListOp(m_op, &context, hash, m_stats);
       }
 
     case TEST_OP_UNDIRTY:
       {
        oid = *(rand_choose(context.oid_not_in_use));
-       cout << m_op << ": " << "undirty oid " << oid << std::endl;
+       context.cout_prefix() << m_op << ": " << "undirty oid " << oid << std::endl;
        return new UndirtyOp(m_op, &context, oid, m_stats);
       }
 
@@ -385,54 +387,54 @@ private:
 
     case TEST_OP_APPEND:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << "append oid " << oid << " current snap is "
+      context.cout_prefix() << "append oid " << oid << " current snap is "
           << context.current_snap << std::endl;
       return new WriteOp(m_op, &context, oid, true, false, m_stats);
 
     case TEST_OP_APPEND_EXCL:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << "append oid (excl) " << oid << " current snap is "
+      context.cout_prefix() << "append oid (excl) " << oid << " current snap is "
           << context.current_snap << std::endl;
       return new WriteOp(m_op, &context, oid, true, true, m_stats);
 
     case TEST_OP_CHUNK_READ:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "chunk read oid " << oid << " target oid " << oid2 << std::endl;
+      context.cout_prefix() << m_op << ": " << "chunk read oid " << oid << " target oid " << oid2 << std::endl;
       return new ChunkReadOp(m_op, &context, oid, context.pool_name, false, m_stats);
 
     case TEST_OP_TIER_PROMOTE:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "tier_promote oid " << oid << std::endl;
+      context.cout_prefix() << m_op << ": " << "tier_promote oid " << oid << std::endl;
       return new TierPromoteOp(m_op, &context, oid, m_stats);
 
     case TEST_OP_TIER_FLUSH:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "tier_flush oid " << oid << std::endl;
+      context.cout_prefix() << m_op << ": " << "tier_flush oid " << oid << std::endl;
       return new TierFlushOp(m_op, &context, oid, m_stats);
 
     case TEST_OP_SET_REDIRECT:
       oid = *(rand_choose(context.oid_not_in_use));
       oid2 = *(rand_choose(context.oid_redirect_not_in_use));
-      cout << m_op << ": " << "set_redirect oid " << oid << " target oid " << oid2 << std::endl;
+      context.cout_prefix() << m_op << ": " << "set_redirect oid " << oid << " target oid " << oid2 << std::endl;
       return new SetRedirectOp(m_op, &context, oid, oid2, context.pool_name, m_stats);
 
     case TEST_OP_UNSET_REDIRECT:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "unset_redirect oid " << oid << std::endl;
+      context.cout_prefix() << m_op << ": " << "unset_redirect oid " << oid << std::endl;
       return new UnsetRedirectOp(m_op, &context, oid, m_stats);
 
     case TEST_OP_SET_CHUNK:
       {
        ceph_assert(m_enable_dedup);
        oid = *(rand_choose(context.oid_not_in_use));
-       cout << m_op << ": " << "set_chunk oid " << oid 
+       context.cout_prefix() << m_op << ": " << "set_chunk oid " << oid
             <<  " target oid " << std::endl;
        return new SetChunkOp(m_op, &context, oid, "", m_stats);
       }
 
     case TEST_OP_TIER_EVICT:
       oid = *(rand_choose(context.oid_not_in_use));
-      cout << m_op << ": " << "tier_evict oid " << oid << std::endl;
+      context.cout_prefix() << m_op << ": " << "tier_evict oid " << oid << std::endl;
       return new TierEvictOp(m_op, &context, oid, m_stats);
 
     default:
@@ -458,6 +460,7 @@ private:
   bool m_set_redirect;
   bool m_set_chunk;
   bool m_enable_dedup;
+  RadosTestContext *context;
 };
 
 int main(int argc, char **argv)
@@ -525,6 +528,7 @@ int main(int argc, char **argv)
   bool set_redirect = false;
   bool set_chunk = false;
   bool enable_dedup = false;
+  bool timestamp = false;
   string chunk_algo = "";
   string chunk_size = "";
   size_t max_attr_len = 20000;
@@ -636,6 +640,8 @@ int main(int argc, char **argv)
       chunk_algo = chunk_algo_types[j].name;
     } else if (strcmp(argv[i], "--dedup_chunk_size") == 0) {
       chunk_size = argv[++i];
+    } else if (strcmp(argv[i], "--timestamps") == 0) {
+      timestamp = true;
     } else {
       cerr << "unknown arg " << argv[i] << std::endl;
       exit(1);
@@ -707,6 +713,7 @@ int main(int argc, char **argv)
     write_fadvise_dontneed,
     low_tier_pool_name,
     enable_dedup,
+    timestamp,
     chunk_algo,
     chunk_size,
     max_attr_len,
@@ -718,7 +725,7 @@ int main(int argc, char **argv)
     op_weights, &stats, max_seconds,
     ec_pool, balance_reads, localize_reads,
     offlen_randomization_ratio,
-    set_redirect, set_chunk, enable_dedup);
+    set_redirect, set_chunk, enable_dedup, &context);
   int r = context.init();
   if (r < 0) {
     cerr << "Error initializing rados test context: "