From: Alex Ainscow Date: Wed, 23 Apr 2025 14:39:30 +0000 (+0100) Subject: test: Add optional timestamps to ceph_test_rados X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=d187babb44c6318d0721460da8a132f4efd57ad9;p=ceph.git 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 --- diff --git a/src/test/osd/RadosModel.h b/src/test/osd/RadosModel.h index 703ce7046516..55f8b7d36036 100644 --- 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::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 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 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 *cb_arg = new std::pair(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 *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 f0acb24a3de7..255b53a3716e 100644 --- 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::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: "