From f2189402831973346db716d52e8160738803bef7 Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Fri, 1 Apr 2022 14:23:44 +0530 Subject: [PATCH 01/10] Added max async export support --- .../otlp/test/otlp_http_log_exporter_test.cc | 10 +- .../sdk/logs/batch_log_processor.h | 48 ++++++-- .../sdk/trace/batch_span_processor.h | 39 ++++-- sdk/src/logs/batch_log_processor.cc | 115 +++++++++++------- sdk/src/trace/batch_span_processor.cc | 104 +++++++++------- sdk/test/logs/batch_log_processor_test.cc | 29 ++++- sdk/test/trace/batch_span_processor_test.cc | 13 +- 7 files changed, 241 insertions(+), 117 deletions(-) diff --git a/exporters/otlp/test/otlp_http_log_exporter_test.cc b/exporters/otlp/test/otlp_http_log_exporter_test.cc index 17723f2ac1..4525c85eca 100644 --- a/exporters/otlp/test/otlp_http_log_exporter_test.cc +++ b/exporters/otlp/test/otlp_http_log_exporter_test.cc @@ -103,9 +103,13 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test std::string attribute_storage_string_value[] = {"vector", "string"}; auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); - provider->AddProcessor( - std::unique_ptr(new sdk::logs::BatchLogProcessor( - std::move(exporter), 5, std::chrono::milliseconds(256), 5, is_async))); + provider->AddProcessor(std::unique_ptr( + new sdk::logs::BatchLogProcessor(std::move(exporter), 5, std::chrono::milliseconds(256), 5 +# ifdef ENABLE_ASYNC_EXPORT + , + is_async +# endif + ))); std::string report_trace_id; std::string report_span_id; diff --git a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h index d93a9d3294..e3b8bc1ec4 100644 --- a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h @@ -13,6 +13,9 @@ # include # include # include +# ifdef ENABLE_ASYNC_EXPORT +# include +# endif OPENTELEMETRY_BEGIN_NAMESPACE namespace sdk @@ -47,6 +50,10 @@ struct BatchLogProcessorOptions * Default implementation is synchronous. */ bool is_export_async = false; + + /* Denotes the maximum number of async exports to continue + */ + size_t max_export_async = 8; # endif }; @@ -72,8 +79,13 @@ class BatchLogProcessor : public LogProcessor std::unique_ptr &&exporter, const size_t max_queue_size = 2048, const std::chrono::milliseconds scheduled_delay_millis = std::chrono::milliseconds(5000), - const size_t max_export_batch_size = 512, - const bool is_export_async = false); + const size_t max_export_batch_size = 512 +# ifdef ENABLE_ASYNC_EXPORT + , + const bool is_export_async = false, + const size_t max_export_async = 8 +# endif + ); /** * Creates a batch log processor by configuring the specified exporter and other parameters @@ -137,21 +149,40 @@ class BatchLogProcessor : public LogProcessor void DrainQueue(); # ifdef ENABLE_ASYNC_EXPORT - /* In case of async export, wait and notify for shutdown to be completed.*/ - void WaitForShutdownCompletion(); + struct AsyncExportData + { + nostd::span> recordables; + }; + + struct ExportDataStorage + { + std::unordered_map> running_async_exports; + std::list> garbage_async_exports; + }; + std::shared_ptr export_data_storage_; + + bool CleanUpGarbageAsyncData(); + + const bool is_export_async_; + const size_t max_export_async_; # endif struct SynchronizationData { /* Synchronization primitives */ - std::condition_variable cv, force_flush_cv, async_shutdown_cv; - std::mutex cv_m, force_flush_cv_m, shutdown_m, async_shutdown_m; + std::condition_variable cv, force_flush_cv; + std::mutex cv_m, force_flush_cv_m, shutdown_m; /* Important boolean flags to handle the workflow of the processor */ std::atomic is_force_wakeup_background_worker; std::atomic is_force_flush_pending; std::atomic is_force_flush_notified; std::atomic is_shutdown; - std::atomic is_async_shutdown_notified; +# ifdef ENABLE_ASYNC_EXPORT + std::mutex async_export_waker_m; + std::condition_variable async_export_waker; + + std::mutex async_export_data_m; +# endif }; /** @@ -171,9 +202,6 @@ class BatchLogProcessor : public LogProcessor const size_t max_queue_size_; const std::chrono::milliseconds scheduled_delay_millis_; const size_t max_export_batch_size_; -# ifdef ENABLE_ASYNC_EXPORT - const bool is_export_async_; -# endif /* The buffer/queue to which the ended logs are added */ common::CircularBuffer buffer_; diff --git a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h index cbd0cddfbb..d11cda1a90 100644 --- a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h @@ -10,6 +10,9 @@ #include #include #include +#ifdef ENABLE_ASYNC_EXPORT +# include +#endif OPENTELEMETRY_BEGIN_NAMESPACE namespace sdk @@ -44,6 +47,10 @@ struct BatchSpanProcessorOptions * Default implementation is synchronous. */ bool is_export_async = false; + + /* Denotes the maximum number of async exports to continue + */ + size_t max_export_async = 8; #endif }; @@ -134,22 +141,41 @@ class BatchSpanProcessor : public SpanProcessor void DrainQueue(); #ifdef ENABLE_ASYNC_EXPORT - /* In case of async export, wait and notify for shutdown to be completed.*/ - void WaitForShutdownCompletion(); + struct AsyncExportData + { + nostd::span> recordables; + }; + + struct ExportDataStorage + { + std::unordered_map> running_async_exports; + std::list> garbage_async_exports; + }; + std::shared_ptr export_data_storage_; + + bool CleanUpGarbageAsyncData(); + + const bool is_export_async_; + const size_t max_export_async_; #endif struct SynchronizationData { /* Synchronization primitives */ - std::condition_variable cv, force_flush_cv, async_shutdown_cv; - std::mutex cv_m, force_flush_cv_m, shutdown_m, async_shutdown_m; + std::condition_variable cv, force_flush_cv; + std::mutex cv_m, force_flush_cv_m, shutdown_m; /* Important boolean flags to handle the workflow of the processor */ std::atomic is_force_wakeup_background_worker; std::atomic is_force_flush_pending; std::atomic is_force_flush_notified; std::atomic is_shutdown; - std::atomic is_async_shutdown_notified; +#ifdef ENABLE_ASYNC_EXPORT + std::mutex async_export_waker_m; + std::condition_variable async_export_waker; + + std::mutex async_export_data_m; +#endif }; /** @@ -169,9 +195,6 @@ class BatchSpanProcessor : public SpanProcessor const size_t max_queue_size_; const std::chrono::milliseconds schedule_delay_millis_; const size_t max_export_batch_size_; -#ifdef ENABLE_ASYNC_EXPORT - const bool is_export_async_; -#endif /* The buffer/queue to which the ended spans are added */ common::CircularBuffer buffer_; diff --git a/sdk/src/logs/batch_log_processor.cc b/sdk/src/logs/batch_log_processor.cc index ee80d21ce7..467325928d 100644 --- a/sdk/src/logs/batch_log_processor.cc +++ b/sdk/src/logs/batch_log_processor.cc @@ -17,14 +17,21 @@ namespace logs BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, const size_t max_queue_size, const std::chrono::milliseconds scheduled_delay_millis, - const size_t max_export_batch_size, - const bool is_export_async) + const size_t max_export_batch_size +# ifdef ENABLE_ASYNC_EXPORT + , + const bool is_export_async, + const size_t max_export_async +# endif + ) : exporter_(std::move(exporter)), max_queue_size_(max_queue_size), scheduled_delay_millis_(scheduled_delay_millis), max_export_batch_size_(max_export_batch_size), # ifdef ENABLE_ASYNC_EXPORT is_export_async_(is_export_async), + max_export_async_(max_export_async), + export_data_storage_(std::make_shared()), # endif buffer_(max_queue_size_), synchronization_data_(std::make_shared()), @@ -34,7 +41,6 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); - synchronization_data_->is_async_shutdown_notified.store(false); } BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, @@ -45,6 +51,8 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, max_export_batch_size_(options.max_export_batch_size), # ifdef ENABLE_ASYNC_EXPORT is_export_async_(options.is_export_async), + max_export_async_(options.max_export_async), + export_data_storage_(std::make_shared()), # endif buffer_(options.max_queue_size), synchronization_data_(std::make_shared()), @@ -54,7 +62,6 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); - synchronization_data_->is_async_shutdown_notified.store(false); } std::unique_ptr BatchLogProcessor::MakeRecordable() noexcept @@ -236,45 +243,61 @@ void BatchLogProcessor::Export() } else { + std::unique_ptr export_data(new AsyncExportData()); + export_data->recordables = + nostd::span>(records_arr.data(), records_arr.size()); + auto ptr = export_data.get(); + { + std::lock_guard lk(synchronization_data_->async_export_data_m); + export_data_storage_->running_async_exports[ptr] = std::move(export_data); + } + std::weak_ptr export_data_watcher = export_data_storage_; std::weak_ptr synchronization_data_watcher = synchronization_data_; - exporter_->Export( - nostd::span>(records_arr.data(), records_arr.size()), - [notify_force_flush, synchronization_data_watcher](sdk::common::ExportResult result) { - // TODO: Print result - if (synchronization_data_watcher.expired()) - { - return true; - } - - NotifyCompletion(notify_force_flush, synchronization_data_watcher.lock()); - return true; - }); + exporter_->Export(ptr->recordables, [notify_force_flush, synchronization_data_watcher, ptr, + export_data_watcher](sdk::common::ExportResult result) { + // TODO: Print result + if (synchronization_data_watcher.expired()) + { + return true; + } + if (export_data_watcher.expired()) + { + return true; + } + auto synchronization_data = synchronization_data_watcher.lock(); + auto export_data = export_data_watcher.lock(); + { + std::lock_guard lk(synchronization_data->async_export_data_m); + export_data->garbage_async_exports.emplace_back( + std::move(export_data->running_async_exports[ptr])); + export_data->running_async_exports.erase(ptr); + } + + NotifyCompletion(notify_force_flush, synchronization_data); + return true; + }); } + // wait for running async exports < max async export allowed + std::unique_lock lock(synchronization_data_->async_export_waker_m); + synchronization_data_->async_export_waker.wait_for(lock, scheduled_delay_millis_, [this] { + std::lock_guard lk(synchronization_data_->async_export_data_m); + return export_data_storage_->running_async_exports.size() <= max_export_async_; + }); + + // Clean up garbage exports + CleanUpGarbageAsyncData(); # endif } while (true); } # ifdef ENABLE_ASYNC_EXPORT -void BatchLogProcessor::WaitForShutdownCompletion() +bool BatchLogProcessor::CleanUpGarbageAsyncData() { - // Since async export is invoked due to shutdown, need to wait - // for async thread to complete. - if (is_export_async_) - { - std::unique_lock lk(synchronization_data_->async_shutdown_m); - while (true) - { - if (synchronization_data_->is_async_shutdown_notified.load()) - { - break; - } + std::lock_guard lk(synchronization_data_->async_export_data_m); + std::list> garbage; + garbage.swap(export_data_storage_->garbage_async_exports); - // When is_async_shutdown_notified.store(true) and async_shutdown_cv.notify_all() is called - // between is_async_shutdown_notified.load() and async_shutdown_cv.wait(). We must not wait - // for ever - synchronization_data_->async_shutdown_cv.wait_for(lk, scheduled_delay_millis_); - } - } + return export_data_storage_->garbage_async_exports.empty() == true; } # endif @@ -292,13 +315,6 @@ void BatchLogProcessor::NotifyCompletion( synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); synchronization_data->force_flush_cv.notify_one(); } - - // Notify the thread which is waiting on shutdown to complete. - if (synchronization_data->is_shutdown.load() == true) - { - synchronization_data->is_async_shutdown_notified.store(true); - synchronization_data->async_shutdown_cv.notify_all(); - } } void BatchLogProcessor::DrainQueue() @@ -312,12 +328,6 @@ void BatchLogProcessor::DrainQueue() } Export(); - -# ifdef ENABLE_ASYNC_EXPORT - // Since async export is invoked due to shutdown, need to wait - // for async thread to complete. - WaitForShutdownCompletion(); -# endif } } @@ -334,6 +344,17 @@ bool BatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcept synchronization_data_->cv.notify_one(); worker_thread_.join(); } +# ifdef ENABLE_ASYNC_EXPORT + // wait for running async exports <= 0 + std::unique_lock lock(synchronization_data_->async_export_waker_m); + synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { + std::lock_guard lk(synchronization_data_->async_export_data_m); + return export_data_storage_->running_async_exports.size() <= 0; + }); + + while (CleanUpGarbageAsyncData() == false) + ; +# endif auto worker_end_time = std::chrono::system_clock::now(); auto offset = std::chrono::duration_cast(worker_end_time - start_time); diff --git a/sdk/src/trace/batch_span_processor.cc b/sdk/src/trace/batch_span_processor.cc index 6a356c17a0..cb42644ba0 100644 --- a/sdk/src/trace/batch_span_processor.cc +++ b/sdk/src/trace/batch_span_processor.cc @@ -24,6 +24,8 @@ BatchSpanProcessor::BatchSpanProcessor(std::unique_ptr &&exporter, max_export_batch_size_(options.max_export_batch_size), #ifdef ENABLE_ASYNC_EXPORT is_export_async_(options.is_export_async), + max_export_async_(options.max_export_async), + export_data_storage_(std::make_shared()), #endif buffer_(max_queue_size_), synchronization_data_(std::make_shared()), @@ -33,7 +35,6 @@ BatchSpanProcessor::BatchSpanProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); - synchronization_data_->is_async_shutdown_notified.store(false); } std::unique_ptr BatchSpanProcessor::MakeRecordable() noexcept @@ -218,45 +219,64 @@ void BatchSpanProcessor::Export() } else { + std::unique_ptr export_data(new AsyncExportData()); + export_data->recordables = + nostd::span>(spans_arr.data(), spans_arr.size()); + auto ptr = export_data.get(); + + { + std::lock_guard lk(synchronization_data_->async_export_data_m); + export_data_storage_->running_async_exports[ptr] = std::move(export_data); + } + std::weak_ptr export_data_watcher = export_data_storage_; + std::weak_ptr synchronization_data_watcher = synchronization_data_; - exporter_->Export( - nostd::span>(spans_arr.data(), spans_arr.size()), - [notify_force_flush, synchronization_data_watcher](sdk::common::ExportResult result) { - // TODO: Print result - if (synchronization_data_watcher.expired()) - { - return true; - } - - NotifyCompletion(notify_force_flush, synchronization_data_watcher.lock()); - return true; - }); + exporter_->Export(ptr->recordables, [notify_force_flush, synchronization_data_watcher, ptr, + export_data_watcher](sdk::common::ExportResult result) { + // TODO: Print result + if (synchronization_data_watcher.expired()) + { + return true; + } + + if (export_data_watcher.expired()) + { + return true; + } + auto synchronization_data = synchronization_data_watcher.lock(); + auto export_data = export_data_watcher.lock(); + { + std::lock_guard lk(synchronization_data->async_export_data_m); + export_data->garbage_async_exports.emplace_back( + std::move(export_data->running_async_exports[ptr])); + export_data->running_async_exports.erase(ptr); + } + NotifyCompletion(notify_force_flush, synchronization_data); + return true; + }); } + + // wait for running async exports < max async export allowed + std::unique_lock lock(synchronization_data_->async_export_waker_m); + synchronization_data_->async_export_waker.wait_for(lock, schedule_delay_millis_, [this] { + std::lock_guard lk(synchronization_data_->async_export_data_m); + return export_data_storage_->running_async_exports.size() <= max_export_async_; + }); + + // Clean up garbage exports + CleanUpGarbageAsyncData(); #endif } while (true); } #ifdef ENABLE_ASYNC_EXPORT -void BatchSpanProcessor::WaitForShutdownCompletion() +bool BatchSpanProcessor::CleanUpGarbageAsyncData() { - // Since async export is invoked due to shutdown, need to wait - // for async thread to complete. - if (is_export_async_) - { - std::unique_lock lk(synchronization_data_->async_shutdown_m); - while (true) - { - if (synchronization_data_->is_async_shutdown_notified.load()) - { - break; - } + std::lock_guard lk(synchronization_data_->async_export_data_m); + std::list> garbage; + garbage.swap(export_data_storage_->garbage_async_exports); - // When is_async_shutdown_notified.store(true) and async_shutdown_cv.notify_all() is called - // between is_async_shutdown_notified.load() and async_shutdown_cv.wait(). We must not wait - // for ever - synchronization_data_->async_shutdown_cv.wait_for(lk, schedule_delay_millis_); - } - } + return export_data_storage_->garbage_async_exports.empty() == true; } #endif @@ -274,13 +294,6 @@ void BatchSpanProcessor::NotifyCompletion( synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); synchronization_data->force_flush_cv.notify_one(); } - - // Notify the thread which is waiting on shutdown to complete. - if (synchronization_data->is_shutdown.load() == true) - { - synchronization_data->is_async_shutdown_notified.store(true); - synchronization_data->async_shutdown_cv.notify_all(); - } } void BatchSpanProcessor::DrainQueue() @@ -294,9 +307,6 @@ void BatchSpanProcessor::DrainQueue() } Export(); -#ifdef ENABLE_ASYNC_EXPORT - WaitForShutdownCompletion(); -#endif } } @@ -313,6 +323,18 @@ bool BatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexcept worker_thread_.join(); } +#ifdef ENABLE_ASYNC_EXPORT + // wait for running async exports <= 0 + std::unique_lock lock(synchronization_data_->async_export_waker_m); + synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { + std::lock_guard lk(synchronization_data_->async_export_data_m); + return export_data_storage_->running_async_exports.size() <= 0; + }); + + while (CleanUpGarbageAsyncData() == false) + ; +#endif + auto worker_end_time = std::chrono::system_clock::now(); auto offset = std::chrono::duration_cast(worker_end_time - start_time); diff --git a/sdk/test/logs/batch_log_processor_test.cc b/sdk/test/logs/batch_log_processor_test.cc index 2ad4eaec67..bba007ee44 100644 --- a/sdk/test/logs/batch_log_processor_test.cc +++ b/sdk/test/logs/batch_log_processor_test.cc @@ -66,6 +66,7 @@ class MockLogExporter final : public LogExporter auto result = Export(records); async_threads_.emplace_back(std::make_shared( [result](std::function &&result_callback) { + std::this_thread::sleep_for(std::chrono::milliseconds(1)); result_callback(result); }, std::move(result_callback))); @@ -116,13 +117,23 @@ class BatchLogProcessorTest : public testing::Test // ::testing::Test const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0), const std::chrono::milliseconds scheduled_delay_millis = std::chrono::milliseconds(5000), const size_t max_queue_size = 2048, - const size_t max_export_batch_size = 512, - const bool is_export_async = false) + const size_t max_export_batch_size = 512 +# ifdef ENABLE_ASYNC_EXPORT + , + const bool is_export_async = false, + const size_t max_export_async = 8 +# endif + ) { return std::shared_ptr(new BatchLogProcessor( std::unique_ptr( new MockLogExporter(logs_received, is_shutdown, is_export_completed, export_delay)), - max_queue_size, scheduled_delay_millis, max_export_batch_size, is_export_async)); + max_queue_size, scheduled_delay_millis, max_export_batch_size +# ifdef ENABLE_ASYNC_EXPORT + , + is_export_async, max_export_async +# endif + )); } }; @@ -176,18 +187,24 @@ TEST_F(BatchLogProcessorTest, TestAsyncShutdown) const std::chrono::milliseconds export_delay(0); const std::chrono::milliseconds scheduled_delay_millis(5000); const size_t max_export_batch_size = 512; - const size_t max_queue_size = 2048; + const size_t max_queue_size = 20; const bool is_export_async = true; + const size_t max_export_async = 5; auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, export_delay, scheduled_delay_millis, max_queue_size, - max_export_batch_size, is_export_async); + max_export_batch_size, is_export_async, max_export_async); // Create a few test log records and send them to the processor - const int num_logs = 3; + const int num_logs = 500; for (int i = 0; i < num_logs; ++i) { + if (i % 20 == 0) + { + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } + auto log = batch_processor->MakeRecordable(); log->SetName("Log" + std::to_string(i)); batch_processor->OnReceive(std::move(log)); diff --git a/sdk/test/trace/batch_span_processor_test.cc b/sdk/test/trace/batch_span_processor_test.cc index 122cbbedfe..e473bdf12d 100644 --- a/sdk/test/trace/batch_span_processor_test.cc +++ b/sdk/test/trace/batch_span_processor_test.cc @@ -67,6 +67,7 @@ class MockSpanExporter final : public sdk::trace::SpanExporter auto result = Export(records); async_threads_.emplace_back(std::make_shared( [result](std::function &&result_callback) { + std::this_thread::sleep_for(std::chrono::milliseconds(1)); result_callback(result); }, std::move(result_callback))); @@ -164,23 +165,31 @@ TEST_F(BatchSpanProcessorTestPeer, TestShutdown) #ifdef ENABLE_ASYNC_EXPORT TEST_F(BatchSpanProcessorTestPeer, TestAsyncShutdown) { + std::shared_ptr> is_export_completed(new std::atomic(false)); std::shared_ptr> is_shutdown(new std::atomic(false)); std::shared_ptr>> spans_received( new std::vector>); sdk::trace::BatchSpanProcessorOptions options{}; - options.is_export_async = true; + options.is_export_async = true; + options.max_export_async = 5; + options.max_queue_size = 20; + options.schedule_delay_millis = std::chrono::milliseconds(500); auto batch_processor = std::shared_ptr(new sdk::trace::BatchSpanProcessor( std::unique_ptr(new MockSpanExporter(spans_received, is_shutdown)), options)); - const int num_spans = 3; + const int num_spans = 500; auto test_spans = GetTestSpans(batch_processor, num_spans); for (int i = 0; i < num_spans; ++i) { + if (i % 20 == 0) + { + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } batch_processor->OnEnd(std::move(test_spans->at(i))); } From 0c8dfcfb2d255fa23ada29368ab90821596dddb6 Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Mon, 4 Apr 2022 09:48:12 +0530 Subject: [PATCH 02/10] Added max async export support --- .github/workflows/ci.yml | 22 +++ ci/do_ci.sh | 7 + .../sdk/logs/batch_log_processor.h | 19 +- .../sdk/trace/batch_span_processor.h | 18 +- sdk/src/logs/batch_log_processor.cc | 173 ++++++++++-------- sdk/src/trace/batch_span_processor.cc | 161 ++++++++-------- sdk/test/logs/batch_log_processor_test.cc | 81 ++++++-- sdk/test/trace/batch_span_processor_test.cc | 74 ++++++-- 8 files changed, 350 insertions(+), 205 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index a851728a2e..ec91b03e81 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -150,6 +150,28 @@ jobs: - name: run tests run: ./ci/do_ci.sh bazel.test + bazel_test_async: + name: Bazel with async export + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v3 + with: + submodules: 'recursive' + - name: Mount Bazel Cache + uses: actions/cache@v3 + env: + cache-name: bazel_cache + with: + path: /home/runner/.cache/bazel + key: bazel_test + - name: setup + run: | + sudo ./ci/setup_thrift.sh dependencies_only + sudo ./ci/setup_ci_environment.sh + sudo ./ci/install_bazelisk.sh + - name: run tests + run: ./ci/do_ci.sh bazel.with_async_export + bazel_with_abseil: name: Bazel with external abseil runs-on: ubuntu-latest diff --git a/ci/do_ci.sh b/ci/do_ci.sh index f9fc8ed215..b4e7760951 100755 --- a/ci/do_ci.sh +++ b/ci/do_ci.sh @@ -66,6 +66,9 @@ BAZEL_TEST_OPTIONS="$BAZEL_OPTIONS --test_output=errors" BAZEL_MACOS_OPTIONS="$BAZEL_OPTIONS --features=-supports_dynamic_linker --build_tag_filters=-jaeger" BAZEL_MACOS_TEST_OPTIONS="$BAZEL_MACOS_OPTIONS --test_output=errors" +BAZEL_OPTIONS_ASYNC="--copt=-DENABLE_METRICS_PREVIEW --copt=-DENABLE_LOGS_PREVIEW --copt=-DENABLE_TEST --copt=-DENABLE_ASYNC_EXPORT_PREVIEW" +BAZEL_TEST_OPTIONS_ASYNC="$BAZEL_OPTIONS_ASYNC --test_output=errors" + BAZEL_STARTUP_OPTIONS="--output_user_root=$HOME/.cache/bazel" export CTEST_OUTPUT_ON_FAILURE=1 @@ -202,6 +205,10 @@ elif [[ "$1" == "bazel.test" ]]; then bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS //... bazel $BAZEL_STARTUP_OPTIONS test $BAZEL_TEST_OPTIONS //... exit 0 +elif [[ "$1" == "bazel.with_async_export" ]]; then + bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS_ASYNC //... + bazel $BAZEL_STARTUP_OPTIONS test $BAZEL_TEST_OPTIONS_ASYNC //... + exit 0 elif [[ "$1" == "bazel.benchmark" ]]; then run_benchmarks exit 0 diff --git a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h index e3b8bc1ec4..556c4d3ee0 100644 --- a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h @@ -14,7 +14,7 @@ # include # include # ifdef ENABLE_ASYNC_EXPORT -# include +# include # endif OPENTELEMETRY_BEGIN_NAMESPACE @@ -149,22 +149,16 @@ class BatchLogProcessor : public LogProcessor void DrainQueue(); # ifdef ENABLE_ASYNC_EXPORT - struct AsyncExportData - { - nostd::span> recordables; - }; - struct ExportDataStorage { - std::unordered_map> running_async_exports; - std::list> garbage_async_exports; + std::queue export_ids; + std::vector export_ids_flag; }; std::shared_ptr export_data_storage_; - bool CleanUpGarbageAsyncData(); - const bool is_export_async_; const size_t max_export_async_; + static constexpr int kInvalidExportId = 0; # endif struct SynchronizationData { @@ -178,9 +172,7 @@ class BatchLogProcessor : public LogProcessor std::atomic is_force_flush_notified; std::atomic is_shutdown; # ifdef ENABLE_ASYNC_EXPORT - std::mutex async_export_waker_m; std::condition_variable async_export_waker; - std::mutex async_export_data_m; # endif }; @@ -195,6 +187,9 @@ class BatchLogProcessor : public LogProcessor static void NotifyCompletion(bool notify_force_flush, const std::shared_ptr &synchronization_data); + void GetWaitAdjustedTime(std::chrono::microseconds &timeout, + std::chrono::time_point &start_time); + /* The configured backend log exporter */ std::unique_ptr exporter_; diff --git a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h index d11cda1a90..eb0df4e22b 100644 --- a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h @@ -11,7 +11,7 @@ #include #include #ifdef ENABLE_ASYNC_EXPORT -# include +# include #endif OPENTELEMETRY_BEGIN_NAMESPACE @@ -141,22 +141,16 @@ class BatchSpanProcessor : public SpanProcessor void DrainQueue(); #ifdef ENABLE_ASYNC_EXPORT - struct AsyncExportData - { - nostd::span> recordables; - }; - struct ExportDataStorage { - std::unordered_map> running_async_exports; - std::list> garbage_async_exports; + std::queue export_ids; + std::vector export_ids_flag; }; std::shared_ptr export_data_storage_; - bool CleanUpGarbageAsyncData(); - const bool is_export_async_; const size_t max_export_async_; + static constexpr int kInvalidExportId = 0; #endif struct SynchronizationData @@ -171,9 +165,7 @@ class BatchSpanProcessor : public SpanProcessor std::atomic is_force_flush_notified; std::atomic is_shutdown; #ifdef ENABLE_ASYNC_EXPORT - std::mutex async_export_waker_m; std::condition_variable async_export_waker; - std::mutex async_export_data_m; #endif }; @@ -188,6 +180,8 @@ class BatchSpanProcessor : public SpanProcessor static void NotifyCompletion(bool notify_force_flush, const std::shared_ptr &synchronization_data); + void GetWaitAdjustedTime(std::chrono::microseconds &timeout, + std::chrono::time_point &start_time); /* The configured backend exporter */ std::unique_ptr exporter_; diff --git a/sdk/src/logs/batch_log_processor.cc b/sdk/src/logs/batch_log_processor.cc index 467325928d..f81a45516a 100644 --- a/sdk/src/logs/batch_log_processor.cc +++ b/sdk/src/logs/batch_log_processor.cc @@ -41,6 +41,14 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); +# ifdef ENABLE_ASYNC_EXPORT + export_data_storage_->export_ids_flag.reserve(max_export_async_); + for (size_t i = 1; i <= max_export_async_; i++) + { + export_data_storage_->export_ids.push(i); + export_data_storage_->export_ids_flag[i - 1] = true; + } +# endif } BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, @@ -62,6 +70,14 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); +# ifdef ENABLE_ASYNC_EXPORT + export_data_storage_->export_ids_flag.reserve(max_export_async_); + for (int i = 1; i <= max_export_async_; i++) + { + export_data_storage_->export_ids.push(i); + export_data_storage_->export_ids_flag[i - 1] = true; + } +# endif } std::unique_ptr BatchLogProcessor::MakeRecordable() noexcept @@ -156,6 +172,7 @@ bool BatchLogProcessor::ForceFlush(std::chrono::microseconds timeout) noexcept } } } + synchronization_data_->is_force_flush_notified.store(false, std::memory_order_release); return result; @@ -243,64 +260,65 @@ void BatchLogProcessor::Export() } else { - std::unique_ptr export_data(new AsyncExportData()); - export_data->recordables = - nostd::span>(records_arr.data(), records_arr.size()); - auto ptr = export_data.get(); + size_t id = kInvalidExportId; { - std::lock_guard lk(synchronization_data_->async_export_data_m); - export_data_storage_->running_async_exports[ptr] = std::move(export_data); - } - std::weak_ptr export_data_watcher = export_data_storage_; - std::weak_ptr synchronization_data_watcher = synchronization_data_; - exporter_->Export(ptr->recordables, [notify_force_flush, synchronization_data_watcher, ptr, - export_data_watcher](sdk::common::ExportResult result) { - // TODO: Print result - if (synchronization_data_watcher.expired()) - { - return true; - } - if (export_data_watcher.expired()) + std::unique_lock lock(synchronization_data_->async_export_data_m); + synchronization_data_->async_export_waker.wait_for(lock, scheduled_delay_millis_, [this] { + return export_data_storage_->export_ids.size() > 0; + }); + if (export_data_storage_->export_ids.size() > 0) { - return true; + id = export_data_storage_->export_ids.front(); + export_data_storage_->export_ids.pop(); + export_data_storage_->export_ids_flag[id - 1] = false; } - auto synchronization_data = synchronization_data_watcher.lock(); - auto export_data = export_data_watcher.lock(); - { - std::lock_guard lk(synchronization_data->async_export_data_m); - export_data->garbage_async_exports.emplace_back( - std::move(export_data->running_async_exports[ptr])); - export_data->running_async_exports.erase(ptr); - } - - NotifyCompletion(notify_force_flush, synchronization_data); - return true; - }); + } + if (id != kInvalidExportId) + { + std::weak_ptr export_data_watcher = export_data_storage_; + std::weak_ptr synchronization_data_watcher = synchronization_data_; + exporter_->Export( + nostd::span>(records_arr.data(), records_arr.size()), + [notify_force_flush, synchronization_data_watcher, export_data_watcher, + id](sdk::common::ExportResult result) { + // TODO: Print result + if (synchronization_data_watcher.expired()) + { + return true; + } + if (export_data_watcher.expired()) + { + return true; + } + bool is_already_notified = false; + auto synchronization_data = synchronization_data_watcher.lock(); + auto export_data = export_data_watcher.lock(); + { + std::unique_lock lk(synchronization_data->async_export_data_m); + // In case callback is called more than once due to some bug in exporter + // we need to ensure export_ids do not contain duplicate. + if (export_data->export_ids_flag[id - 1] == false) + { + export_data->export_ids.push(id); + export_data->export_ids_flag[id - 1] = true; + } + else + { + is_already_notified = true; + } + } + if (is_already_notified == false) + { + NotifyCompletion(notify_force_flush, synchronization_data); + } + return true; + }); + } } - // wait for running async exports < max async export allowed - std::unique_lock lock(synchronization_data_->async_export_waker_m); - synchronization_data_->async_export_waker.wait_for(lock, scheduled_delay_millis_, [this] { - std::lock_guard lk(synchronization_data_->async_export_data_m); - return export_data_storage_->running_async_exports.size() <= max_export_async_; - }); - - // Clean up garbage exports - CleanUpGarbageAsyncData(); # endif } while (true); } -# ifdef ENABLE_ASYNC_EXPORT -bool BatchLogProcessor::CleanUpGarbageAsyncData() -{ - std::lock_guard lk(synchronization_data_->async_export_data_m); - std::list> garbage; - garbage.swap(export_data_storage_->garbage_async_exports); - - return export_data_storage_->garbage_async_exports.empty() == true; -} -# endif - void BatchLogProcessor::NotifyCompletion( bool notify_force_flush, const std::shared_ptr &synchronization_data) @@ -315,6 +333,9 @@ void BatchLogProcessor::NotifyCompletion( synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); synchronization_data->force_flush_cv.notify_one(); } +# ifdef ENABLE_ASYNC_EXPORT + synchronization_data->async_export_waker.notify_all(); +# endif } void BatchLogProcessor::DrainQueue() @@ -331,6 +352,26 @@ void BatchLogProcessor::DrainQueue() } } +void BatchLogProcessor::GetWaitAdjustedTime( + std::chrono::microseconds &timeout, + std::chrono::time_point &start_time) +{ + auto end_time = std::chrono::system_clock::now(); + auto offset = std::chrono::duration_cast(end_time - start_time); + start_time = end_time; + timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( + timeout, std::chrono::microseconds::zero()); + if (timeout > offset && timeout > std::chrono::microseconds::zero()) + { + timeout -= offset; + } + else + { + // Some module use zero as indefinite timeout.So we can not reset timeout to zero here + timeout = std::chrono::microseconds(1); + } +} + bool BatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcept { auto start_time = std::chrono::system_clock::now(); @@ -345,32 +386,16 @@ bool BatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcept worker_thread_.join(); } # ifdef ENABLE_ASYNC_EXPORT - // wait for running async exports <= 0 - std::unique_lock lock(synchronization_data_->async_export_waker_m); - synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { - std::lock_guard lk(synchronization_data_->async_export_data_m); - return export_data_storage_->running_async_exports.size() <= 0; - }); - - while (CleanUpGarbageAsyncData() == false) - ; -# endif - - auto worker_end_time = std::chrono::system_clock::now(); - auto offset = std::chrono::duration_cast(worker_end_time - start_time); - - timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( - timeout, std::chrono::microseconds::zero()); - if (timeout > offset && timeout > std::chrono::microseconds::zero()) - { - timeout -= offset; - } - else + GetWaitAdjustedTime(timeout, start_time); + // wait for all async exports to complete and return if timeout reached. { - // Some module use zero as indefinite timeout.So we can not reset timeout to zero here - timeout = std::chrono::microseconds(1); + std::unique_lock lock(synchronization_data_->async_export_data_m); + synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { + return export_data_storage_->export_ids.size() == max_export_async_; + }); } - +# endif + GetWaitAdjustedTime(timeout, start_time); // Should only shutdown exporter ONCE. if (!already_shutdown && exporter_ != nullptr) { diff --git a/sdk/src/trace/batch_span_processor.cc b/sdk/src/trace/batch_span_processor.cc index cb42644ba0..c15562411e 100644 --- a/sdk/src/trace/batch_span_processor.cc +++ b/sdk/src/trace/batch_span_processor.cc @@ -35,6 +35,15 @@ BatchSpanProcessor::BatchSpanProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); + +#ifdef ENABLE_ASYNC_EXPORT + export_data_storage_->export_ids_flag.reserve(max_export_async_); + for (size_t i = 1; i <= max_export_async_; i++) + { + export_data_storage_->export_ids.push(i); + export_data_storage_->export_ids_flag[i - 1] = true; + } +#endif } std::unique_ptr BatchSpanProcessor::MakeRecordable() noexcept @@ -219,67 +228,58 @@ void BatchSpanProcessor::Export() } else { - std::unique_ptr export_data(new AsyncExportData()); - export_data->recordables = - nostd::span>(spans_arr.data(), spans_arr.size()); - auto ptr = export_data.get(); - + size_t id = kInvalidExportId; { - std::lock_guard lk(synchronization_data_->async_export_data_m); - export_data_storage_->running_async_exports[ptr] = std::move(export_data); - } - std::weak_ptr export_data_watcher = export_data_storage_; - - std::weak_ptr synchronization_data_watcher = synchronization_data_; - exporter_->Export(ptr->recordables, [notify_force_flush, synchronization_data_watcher, ptr, - export_data_watcher](sdk::common::ExportResult result) { - // TODO: Print result - if (synchronization_data_watcher.expired()) - { - return true; - } - - if (export_data_watcher.expired()) + std::unique_lock lock(synchronization_data_->async_export_data_m); + synchronization_data_->async_export_waker.wait_for(lock, schedule_delay_millis_, [this] { + return export_data_storage_->export_ids.size() > 0; + }); + if (export_data_storage_->export_ids.size() > 0) { - return true; + id = export_data_storage_->export_ids.front(); + export_data_storage_->export_ids.pop(); + export_data_storage_->export_ids_flag[id - 1] = false; } - auto synchronization_data = synchronization_data_watcher.lock(); - auto export_data = export_data_watcher.lock(); - { - std::lock_guard lk(synchronization_data->async_export_data_m); - export_data->garbage_async_exports.emplace_back( - std::move(export_data->running_async_exports[ptr])); - export_data->running_async_exports.erase(ptr); - } - NotifyCompletion(notify_force_flush, synchronization_data); - return true; - }); + } + if (id != kInvalidExportId) + { + std::weak_ptr export_data_watcher = export_data_storage_; + + std::weak_ptr synchronization_data_watcher = synchronization_data_; + exporter_->Export( + nostd::span>(spans_arr.data(), spans_arr.size()), + [notify_force_flush, synchronization_data_watcher, export_data_watcher, + id](sdk::common::ExportResult result) { + // TODO: Print result + if (synchronization_data_watcher.expired()) + { + return true; + } + + if (export_data_watcher.expired()) + { + return true; + } + + auto synchronization_data = synchronization_data_watcher.lock(); + auto export_data = export_data_watcher.lock(); + { + std::unique_lock lk(synchronization_data->async_export_data_m); + if (export_data->export_ids_flag[id - 1] == false) + { + export_data->export_ids.push(id); + export_data->export_ids_flag[id - 1] = true; + } + } + NotifyCompletion(notify_force_flush, synchronization_data); + return true; + }); + } } - - // wait for running async exports < max async export allowed - std::unique_lock lock(synchronization_data_->async_export_waker_m); - synchronization_data_->async_export_waker.wait_for(lock, schedule_delay_millis_, [this] { - std::lock_guard lk(synchronization_data_->async_export_data_m); - return export_data_storage_->running_async_exports.size() <= max_export_async_; - }); - - // Clean up garbage exports - CleanUpGarbageAsyncData(); #endif } while (true); } -#ifdef ENABLE_ASYNC_EXPORT -bool BatchSpanProcessor::CleanUpGarbageAsyncData() -{ - std::lock_guard lk(synchronization_data_->async_export_data_m); - std::list> garbage; - garbage.swap(export_data_storage_->garbage_async_exports); - - return export_data_storage_->garbage_async_exports.empty() == true; -} -#endif - void BatchSpanProcessor::NotifyCompletion( bool notify_force_flush, const std::shared_ptr &synchronization_data) @@ -294,6 +294,9 @@ void BatchSpanProcessor::NotifyCompletion( synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); synchronization_data->force_flush_cv.notify_one(); } +#ifdef ENABLE_ASYNC_EXPORT + synchronization_data->async_export_waker.notify_all(); +#endif } void BatchSpanProcessor::DrainQueue() @@ -310,6 +313,26 @@ void BatchSpanProcessor::DrainQueue() } } +void BatchSpanProcessor::GetWaitAdjustedTime( + std::chrono::microseconds &timeout, + std::chrono::time_point &start_time) +{ + auto end_time = std::chrono::system_clock::now(); + auto offset = std::chrono::duration_cast(end_time - start_time); + start_time = end_time; + timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( + timeout, std::chrono::microseconds::zero()); + if (timeout > offset && timeout > std::chrono::microseconds::zero()) + { + timeout -= offset; + } + else + { + // Some module use zero as indefinite timeout.So we can not reset timeout to zero here + timeout = std::chrono::microseconds(1); + } +} + bool BatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexcept { auto start_time = std::chrono::system_clock::now(); @@ -324,33 +347,17 @@ bool BatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexcept } #ifdef ENABLE_ASYNC_EXPORT - // wait for running async exports <= 0 - std::unique_lock lock(synchronization_data_->async_export_waker_m); - synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { - std::lock_guard lk(synchronization_data_->async_export_data_m); - return export_data_storage_->running_async_exports.size() <= 0; - }); - - while (CleanUpGarbageAsyncData() == false) - ; -#endif - - auto worker_end_time = std::chrono::system_clock::now(); - auto offset = std::chrono::duration_cast(worker_end_time - start_time); - - // Fix timeout to meet requirement of wait_for - timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( - timeout, std::chrono::microseconds::zero()); - if (timeout > offset && timeout > std::chrono::microseconds::zero()) - { - timeout -= offset; - } - else + GetWaitAdjustedTime(timeout, start_time); + // wait for all async exports to complete and return if timeout reached. { - // Some module use zero as indefinite timeout.So we can not reset timeout to zero here - timeout = std::chrono::microseconds(1); + std::unique_lock lock(synchronization_data_->async_export_data_m); + synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { + return export_data_storage_->export_ids.size() == max_export_async_; + }); } +#endif + GetWaitAdjustedTime(timeout, start_time); // Should only shutdown exporter ONCE. if (!already_shutdown && exporter_ != nullptr) { diff --git a/sdk/test/logs/batch_log_processor_test.cc b/sdk/test/logs/batch_log_processor_test.cc index bba007ee44..d3980f802a 100644 --- a/sdk/test/logs/batch_log_processor_test.cc +++ b/sdk/test/logs/batch_log_processor_test.cc @@ -26,11 +26,20 @@ class MockLogExporter final : public LogExporter MockLogExporter(std::shared_ptr>> logs_received, std::shared_ptr> is_shutdown, std::shared_ptr> is_export_completed, - const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0)) + const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0) +# ifdef ENABLE_ASYNC_EXPORT + , + int callback_count = 1 +# endif + ) : logs_received_(logs_received), is_shutdown_(is_shutdown), is_export_completed_(is_export_completed), export_delay_(export_delay) +# ifdef ENABLE_ASYNC_EXPORT + , + callback_count_(callback_count) +# endif {} std::unique_ptr MakeRecordable() noexcept @@ -65,9 +74,12 @@ class MockLogExporter final : public LogExporter // We should keep the order of test records auto result = Export(records); async_threads_.emplace_back(std::make_shared( - [result](std::function &&result_callback) { - std::this_thread::sleep_for(std::chrono::milliseconds(1)); - result_callback(result); + [this, + result](std::function &&result_callback) { + for (int i = 0; i < callback_count_; i++) + { + result_callback(result); + } }, std::move(result_callback))); } @@ -99,6 +111,9 @@ class MockLogExporter final : public LogExporter std::shared_ptr> is_export_completed_; const std::chrono::milliseconds export_delay_; std::list> async_threads_; +# ifdef ENABLE_ASYNC_EXPORT + int callback_count_; +# endif }; /** @@ -121,13 +136,19 @@ class BatchLogProcessorTest : public testing::Test // ::testing::Test # ifdef ENABLE_ASYNC_EXPORT , const bool is_export_async = false, - const size_t max_export_async = 8 + const size_t max_export_async = 8, + int callback_count = 1 # endif ) { return std::shared_ptr(new BatchLogProcessor( - std::unique_ptr( - new MockLogExporter(logs_received, is_shutdown, is_export_completed, export_delay)), + std::unique_ptr(new MockLogExporter(logs_received, is_shutdown, + is_export_completed, export_delay +# ifdef ENABLE_ASYNC_EXPORT + , + callback_count +# endif + )), max_queue_size, scheduled_delay_millis, max_export_batch_size # ifdef ENABLE_ASYNC_EXPORT , @@ -187,7 +208,7 @@ TEST_F(BatchLogProcessorTest, TestAsyncShutdown) const std::chrono::milliseconds export_delay(0); const std::chrono::milliseconds scheduled_delay_millis(5000); const size_t max_export_batch_size = 512; - const size_t max_queue_size = 20; + const size_t max_queue_size = 2048; const bool is_export_async = true; const size_t max_export_async = 5; @@ -196,15 +217,10 @@ TEST_F(BatchLogProcessorTest, TestAsyncShutdown) max_export_batch_size, is_export_async, max_export_async); // Create a few test log records and send them to the processor - const int num_logs = 500; + const int num_logs = 2048; for (int i = 0; i < num_logs; ++i) { - if (i % 20 == 0) - { - std::this_thread::sleep_for(std::chrono::milliseconds(1)); - } - auto log = batch_processor->MakeRecordable(); log->SetName("Log" + std::to_string(i)); batch_processor->OnReceive(std::move(log)); @@ -228,6 +244,43 @@ TEST_F(BatchLogProcessorTest, TestAsyncShutdown) // Also check that the processor is shut down at the end EXPECT_TRUE(is_shutdown->load()); } + +TEST_F(BatchLogProcessorTest, TestAsyncShutdownNoCallback) +{ + // initialize a batch log processor with the test exporter + std::shared_ptr>> logs_received( + new std::vector>); + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr> is_export_completed(new std::atomic(false)); + + const std::chrono::milliseconds export_delay(0); + const std::chrono::milliseconds scheduled_delay_millis(5000); + const size_t max_export_batch_size = 512; + const size_t max_queue_size = 2048; + const bool is_export_async = true; + const size_t max_export_async = 5; + + auto batch_processor = GetMockProcessor( + logs_received, is_shutdown, is_export_completed, export_delay, scheduled_delay_millis, + max_queue_size, max_export_batch_size, is_export_async, max_export_async, 0); + + // Create a few test log records and send them to the processor + const int num_logs = 2048; + + for (int i = 0; i < num_logs; ++i) + { + auto log = batch_processor->MakeRecordable(); + log->SetName("Log" + std::to_string(i)); + batch_processor->OnReceive(std::move(log)); + } + + EXPECT_EQ(true, batch_processor->Shutdown(std::chrono::milliseconds(5000))); + // It's safe to shutdown again + EXPECT_TRUE(batch_processor->Shutdown()); + + // Also check that the processor is shut down at the end + EXPECT_TRUE(is_shutdown->load()); +} # endif TEST_F(BatchLogProcessorTest, TestForceFlush) diff --git a/sdk/test/trace/batch_span_processor_test.cc b/sdk/test/trace/batch_span_processor_test.cc index e473bdf12d..e250fd2e55 100644 --- a/sdk/test/trace/batch_span_processor_test.cc +++ b/sdk/test/trace/batch_span_processor_test.cc @@ -24,11 +24,20 @@ class MockSpanExporter final : public sdk::trace::SpanExporter std::shared_ptr> is_shutdown, std::shared_ptr> is_export_completed = std::shared_ptr>(new std::atomic(false)), - const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0)) noexcept + const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0) +#ifdef ENABLE_ASYNC_EXPORT + , + int callback_count = 1 +#endif + ) noexcept : spans_received_(spans_received), is_shutdown_(is_shutdown), is_export_completed_(is_export_completed), export_delay_(export_delay) +#ifdef ENABLE_ASYNC_EXPORT + , + callback_count_(callback_count) +#endif {} std::unique_ptr MakeRecordable() noexcept override @@ -66,9 +75,12 @@ class MockSpanExporter final : public sdk::trace::SpanExporter // We should keep the order of test records auto result = Export(records); async_threads_.emplace_back(std::make_shared( - [result](std::function &&result_callback) { - std::this_thread::sleep_for(std::chrono::milliseconds(1)); - result_callback(result); + [this, + result](std::function &&result_callback) { + for (int i = 0; i < callback_count_; i++) + { + result_callback(result); + } }, std::move(result_callback))); } @@ -102,6 +114,9 @@ class MockSpanExporter final : public sdk::trace::SpanExporter // Meant exclusively to test force flush timeout const std::chrono::milliseconds export_delay_; std::list> async_threads_; +#ifdef ENABLE_ASYNC_EXPORT + int callback_count_; +#endif }; /** @@ -165,35 +180,28 @@ TEST_F(BatchSpanProcessorTestPeer, TestShutdown) #ifdef ENABLE_ASYNC_EXPORT TEST_F(BatchSpanProcessorTestPeer, TestAsyncShutdown) { - std::shared_ptr> is_export_completed(new std::atomic(false)); - std::shared_ptr> is_shutdown(new std::atomic(false)); std::shared_ptr>> spans_received( new std::vector>); + std::shared_ptr> is_shutdown(new std::atomic(false)); sdk::trace::BatchSpanProcessorOptions options{}; - options.is_export_async = true; - options.max_export_async = 5; - options.max_queue_size = 20; - options.schedule_delay_millis = std::chrono::milliseconds(500); + options.is_export_async = true; + options.max_export_async = 5; auto batch_processor = std::shared_ptr(new sdk::trace::BatchSpanProcessor( std::unique_ptr(new MockSpanExporter(spans_received, is_shutdown)), options)); - const int num_spans = 500; + const int num_spans = 2048; auto test_spans = GetTestSpans(batch_processor, num_spans); for (int i = 0; i < num_spans; ++i) { - if (i % 20 == 0) - { - std::this_thread::sleep_for(std::chrono::milliseconds(1)); - } batch_processor->OnEnd(std::move(test_spans->at(i))); } - EXPECT_TRUE(batch_processor->Shutdown()); + EXPECT_TRUE(batch_processor->Shutdown(std::chrono::milliseconds(5000))); // It's safe to shutdown again EXPECT_TRUE(batch_processor->Shutdown()); @@ -206,6 +214,40 @@ TEST_F(BatchSpanProcessorTestPeer, TestAsyncShutdown) EXPECT_TRUE(is_shutdown->load()); } +TEST_F(BatchSpanProcessorTestPeer, TestAsyncShutdownNoCallback) +{ + std::shared_ptr> is_export_completed(new std::atomic(false)); + std::shared_ptr>> spans_received( + new std::vector>); + const std::chrono::milliseconds export_delay(0); + std::shared_ptr> is_shutdown(new std::atomic(false)); + + sdk::trace::BatchSpanProcessorOptions options{}; + options.is_export_async = true; + options.max_export_async = 8; + + auto batch_processor = + std::shared_ptr(new sdk::trace::BatchSpanProcessor( + std::unique_ptr(new MockSpanExporter( + spans_received, is_shutdown, is_export_completed, export_delay, 0)), + options)); + const int num_spans = 2048; + + auto test_spans = GetTestSpans(batch_processor, num_spans); + + for (int i = 0; i < num_spans; ++i) + { + batch_processor->OnEnd(std::move(test_spans->at(i))); + } + + // Shutdown should never block for ever and return on timeout + EXPECT_TRUE(batch_processor->Shutdown(std::chrono::milliseconds(5000))); + // It's safe to shutdown again + EXPECT_TRUE(batch_processor->Shutdown()); + + EXPECT_TRUE(is_shutdown->load()); +} + TEST_F(BatchSpanProcessorTestPeer, TestAsyncForceFlush) { std::shared_ptr> is_shutdown(new std::atomic(false)); From 39df6c8eee70c04dc60b98adccbc479f3c8989e3 Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Wed, 6 Apr 2022 17:39:47 +0530 Subject: [PATCH 03/10] Incorporated Review Comments. Added async flags for most jobs barring few --- ci/do_ci.sh | 36 +++++++++++-------- .../sdk/logs/batch_log_processor.h | 2 +- .../sdk/trace/batch_span_processor.h | 2 +- sdk/src/logs/batch_log_processor.cc | 6 ++-- sdk/src/trace/batch_span_processor.cc | 3 +- 5 files changed, 26 insertions(+), 23 deletions(-) diff --git a/ci/do_ci.sh b/ci/do_ci.sh index b4e7760951..9088310238 100755 --- a/ci/do_ci.sh +++ b/ci/do_ci.sh @@ -25,7 +25,7 @@ function run_benchmarks [ -z "${BENCHMARK_DIR}" ] && export BENCHMARK_DIR=$HOME/benchmark mkdir -p $BENCHMARK_DIR - bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS -c opt -- \ + bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS_ASYNC -c opt -- \ $(bazel query 'attr("tags", "benchmark_result", ...)') echo "" echo "Benchmark results in $BENCHMARK_DIR:" @@ -62,13 +62,13 @@ mkdir -p "${PLUGIN_DIR}" BAZEL_OPTIONS="--copt=-DENABLE_METRICS_PREVIEW --copt=-DENABLE_LOGS_PREVIEW --copt=-DENABLE_TEST" BAZEL_TEST_OPTIONS="$BAZEL_OPTIONS --test_output=errors" -# https://github.com/bazelbuild/bazel/issues/4341 -BAZEL_MACOS_OPTIONS="$BAZEL_OPTIONS --features=-supports_dynamic_linker --build_tag_filters=-jaeger" -BAZEL_MACOS_TEST_OPTIONS="$BAZEL_MACOS_OPTIONS --test_output=errors" - BAZEL_OPTIONS_ASYNC="--copt=-DENABLE_METRICS_PREVIEW --copt=-DENABLE_LOGS_PREVIEW --copt=-DENABLE_TEST --copt=-DENABLE_ASYNC_EXPORT_PREVIEW" BAZEL_TEST_OPTIONS_ASYNC="$BAZEL_OPTIONS_ASYNC --test_output=errors" +# https://github.com/bazelbuild/bazel/issues/4341 +BAZEL_MACOS_OPTIONS="$BAZEL_OPTIONS_ASYNC --features=-supports_dynamic_linker --build_tag_filters=-jaeger" +BAZEL_MACOS_TEST_OPTIONS="$BAZEL_MACOS_OPTIONS --test_output=errors" + BAZEL_STARTUP_OPTIONS="--output_user_root=$HOME/.cache/bazel" export CTEST_OUTPUT_ON_FAILURE=1 @@ -84,6 +84,7 @@ if [[ "$1" == "cmake.test" ]]; then -DWITH_METRICS_PREVIEW=ON \ -DWITH_LOGS_PREVIEW=ON \ -DCMAKE_CXX_FLAGS="-Werror" \ + -DWITH_ASYNC_EXPORT_PREVIEW=ON \ "${SRC_DIR}" make make test @@ -95,6 +96,7 @@ elif [[ "$1" == "cmake.abseil.test" ]]; then -DWITH_METRICS_PREVIEW=ON \ -DWITH_LOGS_PREVIEW=ON \ -DCMAKE_CXX_FLAGS="-Werror" \ + -DWITH_ASYNC_EXPORT_PREVIEW=ON \ -DWITH_ABSEIL=ON \ "${SRC_DIR}" make @@ -105,6 +107,7 @@ elif [[ "$1" == "cmake.c++20.test" ]]; then rm -rf * cmake -DCMAKE_BUILD_TYPE=Debug \ -DCMAKE_CXX_FLAGS="-Werror" \ + -DWITH_ASYNC_EXPORT_PREVIEW=ON \ -DCMAKE_CXX_STANDARD=20 \ "${SRC_DIR}" make @@ -117,6 +120,7 @@ elif [[ "$1" == "cmake.c++20.stl.test" ]]; then -DWITH_METRICS_PREVIEW=ON \ -DWITH_LOGS_PREVIEW=ON \ -DCMAKE_CXX_FLAGS="-Werror" \ + -DWITH_ASYNC_EXPORT_PREVIEW=ON \ -DWITH_STL=ON \ "${SRC_DIR}" make @@ -144,6 +148,7 @@ elif [[ "$1" == "cmake.legacy.exporter.otprotocol.test" ]]; then cmake -DCMAKE_BUILD_TYPE=Debug \ -DCMAKE_CXX_STANDARD=11 \ -DWITH_OTLP=ON \ + -DWITH_ASYNC_EXPORT_PREVIEW=ON \ "${SRC_DIR}" grpc_cpp_plugin=`which grpc_cpp_plugin` proto_make_file="CMakeFiles/opentelemetry_proto.dir/build.make" @@ -156,6 +161,7 @@ elif [[ "$1" == "cmake.exporter.otprotocol.test" ]]; then rm -rf * cmake -DCMAKE_BUILD_TYPE=Debug \ -DWITH_OTLP=ON \ + -DWITH_ASYNC_EXPORT_PREVIEW=ON \ "${SRC_DIR}" grpc_cpp_plugin=`which grpc_cpp_plugin` proto_make_file="CMakeFiles/opentelemetry_proto.dir/build.make" @@ -164,8 +170,8 @@ elif [[ "$1" == "cmake.exporter.otprotocol.test" ]]; then cd exporters/otlp && make test exit 0 elif [[ "$1" == "bazel.with_abseil" ]]; then - bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS --//api:with_abseil=true //... - bazel $BAZEL_STARTUP_OPTIONS test $BAZEL_TEST_OPTIONS --//api:with_abseil=true //... + bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS_ASYNC --//api:with_abseil=true //... + bazel $BAZEL_STARTUP_OPTIONS test $BAZEL_TEST_OPTIONS_ASYNC --//api:with_abseil=true //... exit 0 elif [[ "$1" == "cmake.test_example_plugin" ]]; then # Build the plugin @@ -219,24 +225,24 @@ elif [[ "$1" == "bazel.macos.test" ]]; then elif [[ "$1" == "bazel.legacy.test" ]]; then # we uses C++ future and async() function to test the Prometheus Exporter functionality, # that make this test always fail. ignore Prometheus exporter here. - bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS -- //... -//exporters/otlp/... -//exporters/prometheus/... - bazel $BAZEL_STARTUP_OPTIONS test $BAZEL_TEST_OPTIONS -- //... -//exporters/otlp/... -//exporters/prometheus/... + bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS_ASYNC -- //... -//exporters/otlp/... -//exporters/prometheus/... + bazel $BAZEL_STARTUP_OPTIONS test $BAZEL_TEST_OPTIONS_ASYNC -- //... -//exporters/otlp/... -//exporters/prometheus/... exit 0 elif [[ "$1" == "bazel.noexcept" ]]; then # there are some exceptions and error handling code from the Prometheus and Jaeger Clients # that make this test always fail. ignore Prometheus and Jaeger exporters in the noexcept here. - bazel $BAZEL_STARTUP_OPTIONS build --copt=-fno-exceptions --build_tag_filters=-jaeger $BAZEL_OPTIONS -- //... -//exporters/prometheus/... -//exporters/jaeger/... - bazel $BAZEL_STARTUP_OPTIONS test --copt=-fno-exceptions --build_tag_filters=-jaeger $BAZEL_TEST_OPTIONS -- //... -//exporters/prometheus/... -//exporters/jaeger/... + bazel $BAZEL_STARTUP_OPTIONS build --copt=-fno-exceptions --build_tag_filters=-jaeger $BAZEL_OPTIONS_ASYNC -- //... -//exporters/prometheus/... -//exporters/jaeger/... + bazel $BAZEL_STARTUP_OPTIONS test --copt=-fno-exceptions --build_tag_filters=-jaeger $BAZEL_TEST_OPTIONS_ASYNC -- //... -//exporters/prometheus/... -//exporters/jaeger/... exit 0 elif [[ "$1" == "bazel.asan" ]]; then - bazel $BAZEL_STARTUP_OPTIONS test --config=asan $BAZEL_TEST_OPTIONS //... + bazel $BAZEL_STARTUP_OPTIONS test --config=asan $BAZEL_TEST_OPTIONS_ASYNC //... exit 0 elif [[ "$1" == "bazel.tsan" ]]; then - bazel $BAZEL_STARTUP_OPTIONS test --config=tsan $BAZEL_TEST_OPTIONS //... + bazel $BAZEL_STARTUP_OPTIONS test --config=tsan $BAZEL_TEST_OPTIONS_ASYNC //... exit 0 elif [[ "$1" == "bazel.valgrind" ]]; then - bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS //... - bazel $BAZEL_STARTUP_OPTIONS test --run_under="/usr/bin/valgrind --leak-check=full --error-exitcode=1 --suppressions=\"${SRC_DIR}/ci/valgrind-suppressions\"" $BAZEL_TEST_OPTIONS //... + bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS_ASYNC //... + bazel $BAZEL_STARTUP_OPTIONS test --run_under="/usr/bin/valgrind --leak-check=full --error-exitcode=1 --suppressions=\"${SRC_DIR}/ci/valgrind-suppressions\"" $BAZEL_TEST_OPTIONS_ASYNC //... exit 0 elif [[ "$1" == "benchmark" ]]; then [ -z "${BENCHMARK_DIR}" ] && export BENCHMARK_DIR=$HOME/benchmark diff --git a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h index 556c4d3ee0..4fa9a4eac3 100644 --- a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h @@ -158,7 +158,7 @@ class BatchLogProcessor : public LogProcessor const bool is_export_async_; const size_t max_export_async_; - static constexpr int kInvalidExportId = 0; + static constexpr size_t kInvalidExportId = static_cast(-1); # endif struct SynchronizationData { diff --git a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h index eb0df4e22b..321ce2e4d9 100644 --- a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h @@ -150,7 +150,7 @@ class BatchSpanProcessor : public SpanProcessor const bool is_export_async_; const size_t max_export_async_; - static constexpr int kInvalidExportId = 0; + static constexpr size_t kInvalidExportId = static_cast(-1); #endif struct SynchronizationData diff --git a/sdk/src/logs/batch_log_processor.cc b/sdk/src/logs/batch_log_processor.cc index f81a45516a..aeb9f93024 100644 --- a/sdk/src/logs/batch_log_processor.cc +++ b/sdk/src/logs/batch_log_processor.cc @@ -42,11 +42,10 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); # ifdef ENABLE_ASYNC_EXPORT - export_data_storage_->export_ids_flag.reserve(max_export_async_); + export_data_storage_->export_ids_flag.resize(max_export_async_, true); for (size_t i = 1; i <= max_export_async_; i++) { export_data_storage_->export_ids.push(i); - export_data_storage_->export_ids_flag[i - 1] = true; } # endif } @@ -71,11 +70,10 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); # ifdef ENABLE_ASYNC_EXPORT - export_data_storage_->export_ids_flag.reserve(max_export_async_); + export_data_storage_->export_ids_flag.resize(max_export_async_, true); for (int i = 1; i <= max_export_async_; i++) { export_data_storage_->export_ids.push(i); - export_data_storage_->export_ids_flag[i - 1] = true; } # endif } diff --git a/sdk/src/trace/batch_span_processor.cc b/sdk/src/trace/batch_span_processor.cc index c15562411e..89661bfa82 100644 --- a/sdk/src/trace/batch_span_processor.cc +++ b/sdk/src/trace/batch_span_processor.cc @@ -37,11 +37,10 @@ BatchSpanProcessor::BatchSpanProcessor(std::unique_ptr &&exporter, synchronization_data_->is_shutdown.store(false); #ifdef ENABLE_ASYNC_EXPORT - export_data_storage_->export_ids_flag.reserve(max_export_async_); + export_data_storage_->export_ids_flag.resize(max_export_async_, true); for (size_t i = 1; i <= max_export_async_; i++) { export_data_storage_->export_ids.push(i); - export_data_storage_->export_ids_flag[i - 1] = true; } #endif } From e4bc6e84ffef6a26cd287086726f4dfdcf833f1a Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Wed, 6 Apr 2022 21:48:42 +0530 Subject: [PATCH 04/10] Added CI flags --- ci/do_ci.ps1 | 6 +++++- ci/do_ci.sh | 4 ++-- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/ci/do_ci.ps1 b/ci/do_ci.ps1 index ca7f8abf83..7b60632422 100644 --- a/ci/do_ci.ps1 +++ b/ci/do_ci.ps1 @@ -5,7 +5,7 @@ $action = $args[0] $SRC_DIR=(Get-Item -Path ".\").FullName -$BAZEL_OPTIONS="--copt=-DENABLE_METRICS_PREVIEW --copt=-DENABLE_LOGS_PREVIEW" +$BAZEL_OPTIONS="--copt=-DENABLE_METRICS_PREVIEW --copt=-DENABLE_LOGS_PREVIEW --copt=-DENABLE_ASYNC_EXPORT" $BAZEL_TEST_OPTIONS="$BAZEL_OPTIONS --test_output=errors" if (!(test-path build)) { @@ -32,6 +32,7 @@ switch ($action) { cd "$BUILD_DIR" cmake $SRC_DIR ` -DVCPKG_TARGET_TRIPLET=x64-windows ` + -DWITH_ASYNC_EXPORT_PREVIEW=ON ` "-DCMAKE_TOOLCHAIN_FILE=$VCPKG_DIR\scripts\buildsystems\vcpkg.cmake" $exit = $LASTEXITCODE if ($exit -ne 0) { @@ -52,6 +53,7 @@ switch ($action) { cd "$BUILD_DIR" cmake $SRC_DIR ` -DVCPKG_TARGET_TRIPLET=x64-windows ` + -DWITH_ASYNC_EXPORT_PREVIEW=ON ` -DWITH_OTPROTCOL=ON ` "-DCMAKE_TOOLCHAIN_FILE=$VCPKG_DIR\scripts\buildsystems\vcpkg.cmake" $exit = $LASTEXITCODE @@ -73,6 +75,7 @@ switch ($action) { cd "$BUILD_DIR" cmake $SRC_DIR ` -DVCPKG_TARGET_TRIPLET=x64-windows ` + -DWITH_ASYNC_EXPORT_PREVIEW=ON ` "-DCMAKE_TOOLCHAIN_FILE=$VCPKG_DIR\scripts\buildsystems\vcpkg.cmake" $exit = $LASTEXITCODE if ($exit -ne 0) { @@ -89,6 +92,7 @@ switch ($action) { cd "$BUILD_DIR" cmake $SRC_DIR ` -DVCPKG_TARGET_TRIPLET=x64-windows ` + -DWITH_ASYNC_EXPORT_PREVIEW=ON ` "-DCMAKE_TOOLCHAIN_FILE=$VCPKG_DIR\scripts\buildsystems\vcpkg.cmake" $exit = $LASTEXITCODE if ($exit -ne 0) { diff --git a/ci/do_ci.sh b/ci/do_ci.sh index 9088310238..82c488c266 100755 --- a/ci/do_ci.sh +++ b/ci/do_ci.sh @@ -62,7 +62,7 @@ mkdir -p "${PLUGIN_DIR}" BAZEL_OPTIONS="--copt=-DENABLE_METRICS_PREVIEW --copt=-DENABLE_LOGS_PREVIEW --copt=-DENABLE_TEST" BAZEL_TEST_OPTIONS="$BAZEL_OPTIONS --test_output=errors" -BAZEL_OPTIONS_ASYNC="--copt=-DENABLE_METRICS_PREVIEW --copt=-DENABLE_LOGS_PREVIEW --copt=-DENABLE_TEST --copt=-DENABLE_ASYNC_EXPORT_PREVIEW" +BAZEL_OPTIONS_ASYNC="--copt=-DENABLE_METRICS_PREVIEW --copt=-DENABLE_LOGS_PREVIEW --copt=-DENABLE_TEST --copt=-DENABLE_ASYNC_EXPORT" BAZEL_TEST_OPTIONS_ASYNC="$BAZEL_OPTIONS_ASYNC --test_output=errors" # https://github.com/bazelbuild/bazel/issues/4341 @@ -246,7 +246,7 @@ elif [[ "$1" == "bazel.valgrind" ]]; then exit 0 elif [[ "$1" == "benchmark" ]]; then [ -z "${BENCHMARK_DIR}" ] && export BENCHMARK_DIR=$HOME/benchmark - bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS -c opt -- \ + bazel $BAZEL_STARTUP_OPTIONS build $BAZEL_OPTIONS_ASYNC -c opt -- \ $(bazel query 'attr("tags", "benchmark_result", ...)') echo "" echo "Benchmark results in $BENCHMARK_DIR:" From b15931f501af7476b0194e897d8347d207033861 Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Thu, 14 Apr 2022 12:33:11 +0530 Subject: [PATCH 05/10] Added Separate Async Batch Span/Log Processors to isolate async functionality from sync processors --- .../otlp/test/otlp_http_exporter_test.cc | 219 ++++++++-- .../otlp/test/otlp_http_log_exporter_test.cc | 27 +- .../sdk/logs/async_batch_log_processor.h | 198 +++++++++ .../sdk/logs/batch_log_processor.h | 39 +- .../sdk/trace/async_batch_span_processor.h | 192 +++++++++ .../sdk/trace/batch_span_processor.h | 32 -- sdk/src/logs/CMakeLists.txt | 1 + sdk/src/logs/async_batch_log_processor.cc | 393 ++++++++++++++++++ sdk/src/logs/batch_log_processor.cc | 116 +----- sdk/src/trace/CMakeLists.txt | 1 + sdk/src/trace/async_batch_span_processor.cc | 360 ++++++++++++++++ sdk/src/trace/batch_span_processor.cc | 89 +--- sdk/test/logs/CMakeLists.txt | 7 +- .../logs/async_batch_log_processor_test.cc | 372 +++++++++++++++++ sdk/test/logs/batch_log_processor_test.cc | 204 +-------- sdk/test/trace/CMakeLists.txt | 3 +- .../trace/async_batch_span_processor_test.cc | 375 +++++++++++++++++ sdk/test/trace/batch_span_processor_test.cc | 164 +------- 18 files changed, 2119 insertions(+), 673 deletions(-) create mode 100644 sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h create mode 100644 sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h create mode 100644 sdk/src/logs/async_batch_log_processor.cc create mode 100644 sdk/src/trace/async_batch_span_processor.cc create mode 100644 sdk/test/logs/async_batch_log_processor_test.cc create mode 100644 sdk/test/trace/async_batch_span_processor_test.cc diff --git a/exporters/otlp/test/otlp_http_exporter_test.cc b/exporters/otlp/test/otlp_http_exporter_test.cc index 9d7cd2a5ce..c25c0111b2 100644 --- a/exporters/otlp/test/otlp_http_exporter_test.cc +++ b/exporters/otlp/test/otlp_http_exporter_test.cc @@ -17,6 +17,7 @@ # include "opentelemetry/ext/http/client/http_client_factory.h" # include "opentelemetry/ext/http/client/nosend/http_client_nosend.h" # include "opentelemetry/ext/http/server/http_server.h" +# include "opentelemetry/sdk/trace/async_batch_span_processor.h" # include "opentelemetry/sdk/trace/batch_span_processor.h" # include "opentelemetry/sdk/trace/tracer_provider.h" # include "opentelemetry/trace/provider.h" @@ -85,7 +86,7 @@ class OtlpHttpExporterTestPeer : public ::testing::Test return {new OtlpHttpClient(MakeOtlpHttpClientOptions(content_type), http_client), http_client}; } - void ExportJsonIntegrationTest(bool is_async) + void ExportJsonIntegrationTest() { auto mock_otlp_client = OtlpHttpExporterTestPeer::GetMockOtlpHttpClient(HttpRequestContentType::kJson); @@ -114,9 +115,7 @@ class OtlpHttpExporterTestPeer : public ::testing::Test processor_opts.max_export_batch_size = 5; processor_opts.max_queue_size = 5; processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); -# ifdef ENABLE_ASYNC_EXPORT - processor_opts.is_export_async = is_async; -# endif + auto processor = std::unique_ptr( new sdk::trace::BatchSpanProcessor(std::move(exporter), processor_opts)); auto provider = nostd::shared_ptr( @@ -142,7 +141,7 @@ class OtlpHttpExporterTestPeer : public ::testing::Test auto mock_session = std::static_pointer_cast(no_send_client->session_); EXPECT_CALL(*mock_session, SendRequest) - .WillOnce([&mock_session, report_trace_id, is_async]( + .WillOnce([&mock_session, report_trace_id]( std::shared_ptr callback) { auto check_json = nlohmann::json::parse(mock_session->GetRequest()->body_, nullptr, false); @@ -161,20 +160,97 @@ class OtlpHttpExporterTestPeer : public ::testing::Test } // let the otlp_http_client to continue - if (is_async) + http_client::nosend::Response response; + response.Finish(*callback.get()); + }); + + child_span->End(); + parent_span->End(); + + static_cast(provider.get())->ForceFlush(); + } + +# ifdef ENABLE_ASYNC_EXPORT + void ExportJsonIntegrationTestAsync() + { + auto mock_otlp_client = + OtlpHttpExporterTestPeer::GetMockOtlpHttpClient(HttpRequestContentType::kJson); + auto mock_otlp_http_client = mock_otlp_client.first; + auto client = mock_otlp_client.second; + auto exporter = GetExporter(std::unique_ptr{mock_otlp_http_client}); + + resource::ResourceAttributes resource_attributes = {{"service.name", "unit_test_service"}, + {"tenant.id", "test_user"}}; + resource_attributes["bool_value"] = true; + resource_attributes["int32_value"] = static_cast(1); + resource_attributes["uint32_value"] = static_cast(2); + resource_attributes["int64_value"] = static_cast(0x1100000000LL); + resource_attributes["uint64_value"] = static_cast(0x1200000000ULL); + resource_attributes["double_value"] = static_cast(3.1); + resource_attributes["vec_bool_value"] = std::vector{true, false, true}; + resource_attributes["vec_int32_value"] = std::vector{1, 2}; + resource_attributes["vec_uint32_value"] = std::vector{3, 4}; + resource_attributes["vec_int64_value"] = std::vector{5, 6}; + resource_attributes["vec_uint64_value"] = std::vector{7, 8}; + resource_attributes["vec_double_value"] = std::vector{3.2, 3.3}; + resource_attributes["vec_string_value"] = std::vector{"vector", "string"}; + auto resource = resource::Resource::Create(resource_attributes); + + auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); + processor_opts.max_export_batch_size = 5; + processor_opts.max_queue_size = 5; + processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); + + auto processor = std::unique_ptr( + new sdk::trace::AsyncBatchSpanProcessor(std::move(exporter), processor_opts)); + auto provider = nostd::shared_ptr( + new sdk::trace::TracerProvider(std::move(processor), resource)); + + std::string report_trace_id; + + char trace_id_hex[2 * trace_api::TraceId::kSize] = {0}; + auto tracer = provider->GetTracer("test"); + auto parent_span = tracer->StartSpan("Test parent span"); + + trace_api::StartSpanOptions child_span_opts = {}; + child_span_opts.parent = parent_span->GetContext(); + + auto child_span = tracer->StartSpan("Test child span", child_span_opts); + + nostd::get(child_span_opts.parent) + .trace_id() + .ToLowerBase16(MakeSpan(trace_id_hex)); + report_trace_id.assign(trace_id_hex, sizeof(trace_id_hex)); + + auto no_send_client = std::static_pointer_cast(client); + auto mock_session = + std::static_pointer_cast(no_send_client->session_); + EXPECT_CALL(*mock_session, SendRequest) + .WillOnce([&mock_session, report_trace_id]( + std::shared_ptr callback) { + auto check_json = + nlohmann::json::parse(mock_session->GetRequest()->body_, nullptr, false); + auto resource_span = *check_json["resource_spans"].begin(); + auto instrumentation_library_span = + *resource_span["instrumentation_library_spans"].begin(); + auto span = *instrumentation_library_span["spans"].begin(); + auto received_trace_id = span["trace_id"].get(); + EXPECT_EQ(received_trace_id, report_trace_id); + + auto custom_header = mock_session->GetRequest()->headers_.find("Custom-Header-Key"); + ASSERT_TRUE(custom_header != mock_session->GetRequest()->headers_.end()); + if (custom_header != mock_session->GetRequest()->headers_.end()) { - std::thread async_finish{[callback]() { - std::this_thread::sleep_for(std::chrono::milliseconds(100)); - http_client::nosend::Response response; - response.Finish(*callback.get()); - }}; - async_finish.detach(); + EXPECT_EQ("Custom-Header-Value", custom_header->second); } - else - { + + // let the otlp_http_client to continue + std::thread async_finish{[callback]() { + std::this_thread::sleep_for(std::chrono::milliseconds(100)); http_client::nosend::Response response; response.Finish(*callback.get()); - } + }}; + async_finish.detach(); }); child_span->End(); @@ -182,8 +258,9 @@ class OtlpHttpExporterTestPeer : public ::testing::Test static_cast(provider.get())->ForceFlush(); } +# endif - void ExportBinaryIntegrationTest(bool is_async) + void ExportBinaryIntegrationTest() { auto mock_otlp_client = OtlpHttpExporterTestPeer::GetMockOtlpHttpClient(HttpRequestContentType::kBinary); @@ -212,9 +289,7 @@ class OtlpHttpExporterTestPeer : public ::testing::Test processor_opts.max_export_batch_size = 5; processor_opts.max_queue_size = 5; processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); -# ifdef ENABLE_ASYNC_EXPORT - processor_opts.is_export_async = is_async; -# endif + auto processor = std::unique_ptr( new sdk::trace::BatchSpanProcessor(std::move(exporter), processor_opts)); auto provider = nostd::shared_ptr( @@ -239,7 +314,7 @@ class OtlpHttpExporterTestPeer : public ::testing::Test auto mock_session = std::static_pointer_cast(no_send_client->session_); EXPECT_CALL(*mock_session, SendRequest) - .WillOnce([&mock_session, report_trace_id, is_async]( + .WillOnce([&mock_session, report_trace_id]( std::shared_ptr callback) { opentelemetry::proto::collector::trace::v1::ExportTraceServiceRequest request_body; request_body.ParseFromArray(&mock_session->GetRequest()->body_[0], @@ -255,21 +330,94 @@ class OtlpHttpExporterTestPeer : public ::testing::Test EXPECT_EQ("Custom-Header-Value", custom_header->second); } - // let the otlp_http_client to continue - if (is_async) + http_client::nosend::Response response; + response.Finish(*callback.get()); + }); + + child_span->End(); + parent_span->End(); + + static_cast(provider.get())->ForceFlush(); + } + +# ifdef ENABLE_ASYNC_EXPORT + void ExportBinaryIntegrationTestAsync() + { + auto mock_otlp_client = + OtlpHttpExporterTestPeer::GetMockOtlpHttpClient(HttpRequestContentType::kBinary); + auto mock_otlp_http_client = mock_otlp_client.first; + auto client = mock_otlp_client.second; + auto exporter = GetExporter(std::unique_ptr{mock_otlp_http_client}); + + resource::ResourceAttributes resource_attributes = {{"service.name", "unit_test_service"}, + {"tenant.id", "test_user"}}; + resource_attributes["bool_value"] = true; + resource_attributes["int32_value"] = static_cast(1); + resource_attributes["uint32_value"] = static_cast(2); + resource_attributes["int64_value"] = static_cast(0x1100000000LL); + resource_attributes["uint64_value"] = static_cast(0x1200000000ULL); + resource_attributes["double_value"] = static_cast(3.1); + resource_attributes["vec_bool_value"] = std::vector{true, false, true}; + resource_attributes["vec_int32_value"] = std::vector{1, 2}; + resource_attributes["vec_uint32_value"] = std::vector{3, 4}; + resource_attributes["vec_int64_value"] = std::vector{5, 6}; + resource_attributes["vec_uint64_value"] = std::vector{7, 8}; + resource_attributes["vec_double_value"] = std::vector{3.2, 3.3}; + resource_attributes["vec_string_value"] = std::vector{"vector", "string"}; + auto resource = resource::Resource::Create(resource_attributes); + + auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); + processor_opts.max_export_batch_size = 5; + processor_opts.max_queue_size = 5; + processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); + + auto processor = std::unique_ptr( + new sdk::trace::AsyncBatchSpanProcessor(std::move(exporter), processor_opts)); + auto provider = nostd::shared_ptr( + new sdk::trace::TracerProvider(std::move(processor), resource)); + + std::string report_trace_id; + + uint8_t trace_id_binary[trace_api::TraceId::kSize] = {0}; + auto tracer = provider->GetTracer("test"); + auto parent_span = tracer->StartSpan("Test parent span"); + + trace_api::StartSpanOptions child_span_opts = {}; + child_span_opts.parent = parent_span->GetContext(); + + auto child_span = tracer->StartSpan("Test child span", child_span_opts); + nostd::get(child_span_opts.parent) + .trace_id() + .CopyBytesTo(MakeSpan(trace_id_binary)); + report_trace_id.assign(reinterpret_cast(trace_id_binary), sizeof(trace_id_binary)); + + auto no_send_client = std::static_pointer_cast(client); + auto mock_session = + std::static_pointer_cast(no_send_client->session_); + EXPECT_CALL(*mock_session, SendRequest) + .WillOnce([&mock_session, report_trace_id]( + std::shared_ptr callback) { + opentelemetry::proto::collector::trace::v1::ExportTraceServiceRequest request_body; + request_body.ParseFromArray(&mock_session->GetRequest()->body_[0], + static_cast(mock_session->GetRequest()->body_.size())); + auto received_trace_id = + request_body.resource_spans(0).instrumentation_library_spans(0).spans(0).trace_id(); + EXPECT_EQ(received_trace_id, report_trace_id); + + auto custom_header = mock_session->GetRequest()->headers_.find("Custom-Header-Key"); + ASSERT_TRUE(custom_header != mock_session->GetRequest()->headers_.end()); + if (custom_header != mock_session->GetRequest()->headers_.end()) { - std::thread async_finish{[callback]() { - std::this_thread::sleep_for(std::chrono::milliseconds(100)); - http_client::nosend::Response response; - response.Finish(*callback.get()); - }}; - async_finish.detach(); + EXPECT_EQ("Custom-Header-Value", custom_header->second); } - else - { + + // let the otlp_http_client to continue + std::thread async_finish{[callback]() { + std::this_thread::sleep_for(std::chrono::milliseconds(100)); http_client::nosend::Response response; response.Finish(*callback.get()); - } + }}; + async_finish.detach(); }); child_span->End(); @@ -277,31 +425,32 @@ class OtlpHttpExporterTestPeer : public ::testing::Test static_cast(provider.get())->ForceFlush(); } +# endif }; // Create spans, let processor call Export() TEST_F(OtlpHttpExporterTestPeer, ExportJsonIntegrationTestSync) { - ExportJsonIntegrationTest(false); + ExportJsonIntegrationTest(); } # ifdef ENABLE_ASYNC_EXPORT TEST_F(OtlpHttpExporterTestPeer, ExportJsonIntegrationTestAsync) { - ExportJsonIntegrationTest(true); + ExportJsonIntegrationTestAsync(); } # endif // Create spans, let processor call Export() TEST_F(OtlpHttpExporterTestPeer, ExportBinaryIntegrationTestSync) { - ExportBinaryIntegrationTest(false); + ExportBinaryIntegrationTest(); } # ifdef ENABLE_ASYNC_EXPORT TEST_F(OtlpHttpExporterTestPeer, ExportBinaryIntegrationTestAsync) { - ExportBinaryIntegrationTest(true); + ExportBinaryIntegrationTestAsync(); } # endif diff --git a/exporters/otlp/test/otlp_http_log_exporter_test.cc b/exporters/otlp/test/otlp_http_log_exporter_test.cc index 4525c85eca..a2d125d903 100644 --- a/exporters/otlp/test/otlp_http_log_exporter_test.cc +++ b/exporters/otlp/test/otlp_http_log_exporter_test.cc @@ -20,6 +20,7 @@ # include "opentelemetry/ext/http/client/nosend/http_client_nosend.h" # include "opentelemetry/ext/http/server/http_server.h" # include "opentelemetry/logs/provider.h" +# include "opentelemetry/sdk/logs/async_batch_log_processor.h" # include "opentelemetry/sdk/logs/batch_log_processor.h" # include "opentelemetry/sdk/logs/exporter.h" # include "opentelemetry/sdk/logs/log_record.h" @@ -103,13 +104,15 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test std::string attribute_storage_string_value[] = {"vector", "string"}; auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); - provider->AddProcessor(std::unique_ptr( - new sdk::logs::BatchLogProcessor(std::move(exporter), 5, std::chrono::milliseconds(256), 5 # ifdef ENABLE_ASYNC_EXPORT - , - is_async + provider->AddProcessor( + std::unique_ptr(new sdk::logs::AsyncBatchLogProcessor( + std::move(exporter), 5, std::chrono::milliseconds(256), 5))); +# else + provider->AddProcessor( + std::unique_ptr(new sdk::logs::BatchLogProcessor( + std::move(exporter), 5, std::chrono::milliseconds(256), 5))); # endif - ))); std::string report_trace_id; std::string report_span_id; @@ -213,16 +216,22 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test double attribute_storage_double_value[] = {3.2, 3.3}; std::string attribute_storage_string_value[] = {"vector", "string"}; + auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); +# ifdef ENABLE_ASYNC_EXPORT + sdk::logs::AsyncBatchLogProcessorOptions processor_options; + processor_options.max_export_batch_size = 5; + processor_options.max_queue_size = 5; + processor_options.schedule_delay_millis = std::chrono::milliseconds(256); + provider->AddProcessor(std::unique_ptr( + new sdk::logs::AsyncBatchLogProcessor(std::move(exporter), processor_options))); +# else sdk::logs::BatchLogProcessorOptions processor_options; processor_options.max_export_batch_size = 5; processor_options.max_queue_size = 5; processor_options.schedule_delay_millis = std::chrono::milliseconds(256); -# ifdef ENABLE_ASYNC_EXPORT - processor_options.is_export_async = is_async; -# endif - auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); provider->AddProcessor(std::unique_ptr( new sdk::logs::BatchLogProcessor(std::move(exporter), processor_options))); +# endif std::string report_trace_id; std::string report_span_id; diff --git a/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h new file mode 100644 index 0000000000..8c097af4f6 --- /dev/null +++ b/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h @@ -0,0 +1,198 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +#pragma once +#ifdef ENABLE_LOGS_PREVIEW +# ifdef ENABLE_ASYNC_EXPORT + +# include "opentelemetry/sdk/common/circular_buffer.h" +# include "opentelemetry/sdk/logs/exporter.h" +# include "opentelemetry/sdk/logs/processor.h" + +# include +# include +# include +# include +# include +# ifdef ENABLE_ASYNC_EXPORT +# include +# endif + +OPENTELEMETRY_BEGIN_NAMESPACE +namespace sdk +{ + +namespace logs +{ + +/** + * Struct to hold batch SpanProcessor options. + */ +struct AsyncBatchLogProcessorOptions +{ + /** + * The maximum buffer/queue size. After the size is reached, spans are + * dropped. + */ + size_t max_queue_size = 2048; + + /* The time interval between two consecutive exports. */ + std::chrono::milliseconds schedule_delay_millis = std::chrono::milliseconds(5000); + + /** + * The maximum batch size of every export. It must be smaller or + * equal to max_queue_size. + */ + size_t max_export_batch_size = 512; + + /* Denotes the maximum number of async exports to continue + */ + size_t max_export_async = 8; +}; + +/** + * This is an implementation of the LogProcessor which creates batches of finished logs and passes + * the export-friendly log data representations to the configured LogExporter. + */ +class AsyncBatchLogProcessor : public LogProcessor +{ +public: + /** + * Creates a batch log processor by configuring the specified exporter and other parameters + * as per the official, language-agnostic opentelemetry specs. + * + * @param exporter - The backend exporter to pass the logs to + * @param max_queue_size - The maximum buffer/queue size. After the size is reached, logs are + * dropped. + * @param scheduled_delay_millis - The time interval between two consecutive exports. + * @param max_export_batch_size - The maximum batch size of every export. It must be smaller or + * equal to max_queue_size + */ + explicit AsyncBatchLogProcessor( + std::unique_ptr &&exporter, + const size_t max_queue_size = 2048, + const std::chrono::milliseconds scheduled_delay_millis = std::chrono::milliseconds(5000), + const size_t max_export_batch_size = 512, + const size_t max_export_async = 8); + + /** + * Creates a batch log processor by configuring the specified exporter and other parameters + * as per the official, language-agnostic opentelemetry specs. + * + * @param exporter - The backend exporter to pass the logs to + * @param options - The batch SpanProcessor options. + */ + explicit AsyncBatchLogProcessor(std::unique_ptr &&exporter, + const AsyncBatchLogProcessorOptions &options); + + /** Makes a new recordable **/ + std::unique_ptr MakeRecordable() noexcept override; + + /** + * Called when the Logger's log method creates a log record + * @param record the log record + */ + + void OnReceive(std::unique_ptr &&record) noexcept override; + + /** + * Export all log records that have not been exported yet. + * + * NOTE: Timeout functionality not supported yet. + */ + bool ForceFlush( + std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; + + /** + * Shuts down the processor and does any cleanup required. Completely drains the buffer/queue of + * all its logs and passes them to the exporter. Any subsequent calls to + * ForceFlush or Shutdown will return immediately without doing anything. + * + * NOTE: Timeout functionality not supported yet. + */ + bool Shutdown( + std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; + + /** + * Class destructor which invokes the Shutdown() method. + */ + virtual ~AsyncBatchLogProcessor() override; + +private: + /** + * The background routine performed by the worker thread. + */ + void DoBackgroundWork(); + + /** + * Exports all logs to the configured exporter. + * + */ + void Export(); + + /** + * Called when Shutdown() is invoked. Completely drains the queue of all log records and + * passes them to the exporter. + */ + void DrainQueue(); + + struct ExportDataStorage + { + std::queue export_ids; + std::vector export_ids_flag; + }; + std::shared_ptr export_data_storage_; + + const size_t max_export_async_; + static constexpr size_t kInvalidExportId = static_cast(-1); + + struct SynchronizationData + { + /* Synchronization primitives */ + std::condition_variable cv, force_flush_cv; + std::mutex cv_m, force_flush_cv_m, shutdown_m; + + /* Important boolean flags to handle the workflow of the processor */ + std::atomic is_force_wakeup_background_worker; + std::atomic is_force_flush_pending; + std::atomic is_force_flush_notified; + std::atomic is_shutdown; + + std::condition_variable async_export_waker; + std::mutex async_export_data_m; + }; + + /** + * @brief Notify completion of shutdown and force flush. This may be called from the any thread at + * any time + * + * @param notify_force_flush Flag to indicate whether to notify force flush completion. + * @param synchronization_data Synchronization data to be notified. + */ + static void NotifyCompletion(bool notify_force_flush, + const std::shared_ptr &synchronization_data); + + void GetWaitAdjustedTime(std::chrono::microseconds &timeout, + std::chrono::time_point &start_time); + + /* The configured backend log exporter */ + std::unique_ptr exporter_; + + /* Configurable parameters as per the official *trace* specs */ + const size_t max_queue_size_; + const std::chrono::milliseconds scheduled_delay_millis_; + const size_t max_export_batch_size_; + /* The buffer/queue to which the ended logs are added */ + common::CircularBuffer buffer_; + + std::shared_ptr synchronization_data_; + + /* The background worker thread */ + std::thread worker_thread_; +}; + +} // namespace logs +} // namespace sdk +OPENTELEMETRY_END_NAMESPACE +# endif +#endif diff --git a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h index 4fa9a4eac3..636281704d 100644 --- a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h @@ -13,9 +13,6 @@ # include # include # include -# ifdef ENABLE_ASYNC_EXPORT -# include -# endif OPENTELEMETRY_BEGIN_NAMESPACE namespace sdk @@ -43,18 +40,6 @@ struct BatchLogProcessorOptions * equal to max_queue_size. */ size_t max_export_batch_size = 512; - -# ifdef ENABLE_ASYNC_EXPORT - /** - * Determines whether the export happens asynchronously. - * Default implementation is synchronous. - */ - bool is_export_async = false; - - /* Denotes the maximum number of async exports to continue - */ - size_t max_export_async = 8; -# endif }; /** @@ -79,13 +64,7 @@ class BatchLogProcessor : public LogProcessor std::unique_ptr &&exporter, const size_t max_queue_size = 2048, const std::chrono::milliseconds scheduled_delay_millis = std::chrono::milliseconds(5000), - const size_t max_export_batch_size = 512 -# ifdef ENABLE_ASYNC_EXPORT - , - const bool is_export_async = false, - const size_t max_export_async = 8 -# endif - ); + const size_t max_export_batch_size = 512); /** * Creates a batch log processor by configuring the specified exporter and other parameters @@ -148,18 +127,6 @@ class BatchLogProcessor : public LogProcessor */ void DrainQueue(); -# ifdef ENABLE_ASYNC_EXPORT - struct ExportDataStorage - { - std::queue export_ids; - std::vector export_ids_flag; - }; - std::shared_ptr export_data_storage_; - - const bool is_export_async_; - const size_t max_export_async_; - static constexpr size_t kInvalidExportId = static_cast(-1); -# endif struct SynchronizationData { /* Synchronization primitives */ @@ -171,10 +138,6 @@ class BatchLogProcessor : public LogProcessor std::atomic is_force_flush_pending; std::atomic is_force_flush_notified; std::atomic is_shutdown; -# ifdef ENABLE_ASYNC_EXPORT - std::condition_variable async_export_waker; - std::mutex async_export_data_m; -# endif }; /** diff --git a/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h new file mode 100644 index 0000000000..6798a3f507 --- /dev/null +++ b/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h @@ -0,0 +1,192 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +#pragma once +#ifdef ENABLE_ASYNC_EXPORT + +# include "opentelemetry/sdk/common/circular_buffer.h" +# include "opentelemetry/sdk/trace/exporter.h" +# include "opentelemetry/sdk/trace/processor.h" + +# include +# include +# include +# include + +OPENTELEMETRY_BEGIN_NAMESPACE +namespace sdk +{ + +namespace trace +{ + +/** + * Struct to hold batch SpanProcessor options. + */ +struct AsyncBatchSpanProcessorOptions +{ + /** + * The maximum buffer/queue size. After the size is reached, spans are + * dropped. + */ + size_t max_queue_size = 2048; + + /* The time interval between two consecutive exports. */ + std::chrono::milliseconds schedule_delay_millis = std::chrono::milliseconds(5000); + + /** + * The maximum batch size of every export. It must be smaller or + * equal to max_queue_size. + */ + size_t max_export_batch_size = 512; + + /* Denotes the maximum number of async exports to continue + */ + size_t max_export_async = 8; +}; + +/** + * This is an implementation of the SpanProcessor which creates batches of finished spans and passes + * the export-friendly span data representations to the configured SpanExporter. + */ +class AsyncBatchSpanProcessor : public SpanProcessor +{ +public: + /** + * Creates a batch span processor by configuring the specified exporter and other parameters + * as per the official, language-agnostic opentelemetry specs. + * + * @param exporter - The backend exporter to pass the ended spans to. + * @param options - The batch SpanProcessor options. + */ + AsyncBatchSpanProcessor(std::unique_ptr &&exporter, + const AsyncBatchSpanProcessorOptions &options); + + /** + * Requests a Recordable(Span) from the configured exporter. + * + * @return A recordable generated by the backend exporter + */ + std::unique_ptr MakeRecordable() noexcept override; + + /** + * Called when a span is started. + * + * NOTE: This method is a no-op. + * + * @param span - The span that just started + * @param parent_context - The parent context of the span that just started + */ + void OnStart(Recordable &span, + const opentelemetry::trace::SpanContext &parent_context) noexcept override; + + /** + * Called when a span ends. + * + * @param span - A recordable for a span that just ended + */ + void OnEnd(std::unique_ptr &&span) noexcept override; + + /** + * Export all ended spans that have not been exported yet. + * + * NOTE: Timeout functionality not supported yet. + */ + bool ForceFlush( + std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; + + /** + * Shuts down the processor and does any cleanup required. Completely drains the buffer/queue of + * all its ended spans and passes them to the exporter. Any subsequent calls to OnStart, OnEnd, + * ForceFlush or Shutdown will return immediately without doing anything. + * + * NOTE: Timeout functionality not supported yet. + */ + bool Shutdown( + std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; + + /** + * Class destructor which invokes the Shutdown() method. The Shutdown() method is supposed to be + * invoked when the Tracer is shutdown (as per other languages), but the C++ Tracer only takes + * shared ownership of the processor, and thus doesn't call Shutdown (as the processor might be + * shared with other Tracers). + */ + ~AsyncBatchSpanProcessor(); + +private: + /** + * The background routine performed by the worker thread. + */ + void DoBackgroundWork(); + + /** + * Exports all ended spans to the configured exporter. + * + */ + void Export(); + + /** + * Called when Shutdown() is invoked. Completely drains the queue of all its ended spans and + * passes them to the exporter. + */ + void DrainQueue(); + + struct ExportDataStorage + { + std::queue export_ids; + std::vector export_ids_flag; + }; + std::shared_ptr export_data_storage_; + + const size_t max_export_async_; + static constexpr size_t kInvalidExportId = static_cast(-1); + + struct SynchronizationData + { + /* Synchronization primitives */ + std::condition_variable cv, force_flush_cv; + std::mutex cv_m, force_flush_cv_m, shutdown_m; + + /* Important boolean flags to handle the workflow of the processor */ + std::atomic is_force_wakeup_background_worker; + std::atomic is_force_flush_pending; + std::atomic is_force_flush_notified; + std::atomic is_shutdown; + + std::condition_variable async_export_waker; + std::mutex async_export_data_m; + }; + + /** + * @brief Notify completion of shutdown and force flush. This may be called from the any thread at + * any time + * + * @param notify_force_flush Flag to indicate whether to notify force flush completion. + * @param synchronization_data Synchronization data to be notified. + */ + static void NotifyCompletion(bool notify_force_flush, + const std::shared_ptr &synchronization_data); + + void GetWaitAdjustedTime(std::chrono::microseconds &timeout, + std::chrono::time_point &start_time); + /* The configured backend exporter */ + std::unique_ptr exporter_; + + /* Configurable parameters as per the official specs */ + const size_t max_queue_size_; + const std::chrono::milliseconds schedule_delay_millis_; + const size_t max_export_batch_size_; + + /* The buffer/queue to which the ended spans are added */ + common::CircularBuffer buffer_; + + std::shared_ptr synchronization_data_; + + /* The background worker thread */ + std::thread worker_thread_; +}; + +} // namespace trace +} // namespace sdk +OPENTELEMETRY_END_NAMESPACE +#endif \ No newline at end of file diff --git a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h index 321ce2e4d9..e404e41878 100644 --- a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h @@ -10,9 +10,6 @@ #include #include #include -#ifdef ENABLE_ASYNC_EXPORT -# include -#endif OPENTELEMETRY_BEGIN_NAMESPACE namespace sdk @@ -40,18 +37,6 @@ struct BatchSpanProcessorOptions * equal to max_queue_size. */ size_t max_export_batch_size = 512; - -#ifdef ENABLE_ASYNC_EXPORT - /** - * Determines whether the export happens asynchronously. - * Default implementation is synchronous. - */ - bool is_export_async = false; - - /* Denotes the maximum number of async exports to continue - */ - size_t max_export_async = 8; -#endif }; /** @@ -140,19 +125,6 @@ class BatchSpanProcessor : public SpanProcessor */ void DrainQueue(); -#ifdef ENABLE_ASYNC_EXPORT - struct ExportDataStorage - { - std::queue export_ids; - std::vector export_ids_flag; - }; - std::shared_ptr export_data_storage_; - - const bool is_export_async_; - const size_t max_export_async_; - static constexpr size_t kInvalidExportId = static_cast(-1); -#endif - struct SynchronizationData { /* Synchronization primitives */ @@ -164,10 +136,6 @@ class BatchSpanProcessor : public SpanProcessor std::atomic is_force_flush_pending; std::atomic is_force_flush_notified; std::atomic is_shutdown; -#ifdef ENABLE_ASYNC_EXPORT - std::condition_variable async_export_waker; - std::mutex async_export_data_m; -#endif }; /** diff --git a/sdk/src/logs/CMakeLists.txt b/sdk/src/logs/CMakeLists.txt index 20f13324e7..1b1db9e778 100644 --- a/sdk/src/logs/CMakeLists.txt +++ b/sdk/src/logs/CMakeLists.txt @@ -4,6 +4,7 @@ add_library( logger.cc simple_log_processor.cc batch_log_processor.cc + async_batch_log_processor.cc logger_context.cc multi_log_processor.cc multi_recordable.cc) diff --git a/sdk/src/logs/async_batch_log_processor.cc b/sdk/src/logs/async_batch_log_processor.cc new file mode 100644 index 0000000000..c23ffbe042 --- /dev/null +++ b/sdk/src/logs/async_batch_log_processor.cc @@ -0,0 +1,393 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +#ifdef ENABLE_LOGS_PREVIEW +# ifdef ENABLE_ASYNC_EXPORT +# include "opentelemetry/sdk/logs/async_batch_log_processor.h" +# include "opentelemetry/common/spin_lock_mutex.h" + +# include +using opentelemetry::sdk::common::AtomicUniquePtr; +using opentelemetry::sdk::common::CircularBufferRange; + +OPENTELEMETRY_BEGIN_NAMESPACE +namespace sdk +{ +namespace logs +{ +AsyncBatchLogProcessor::AsyncBatchLogProcessor( + std::unique_ptr &&exporter, + const size_t max_queue_size, + const std::chrono::milliseconds scheduled_delay_millis, + const size_t max_export_batch_size, + const size_t max_export_async) + : exporter_(std::move(exporter)), + max_queue_size_(max_queue_size), + scheduled_delay_millis_(scheduled_delay_millis), + max_export_batch_size_(max_export_batch_size), + max_export_async_(max_export_async), + export_data_storage_(std::make_shared()), + buffer_(max_queue_size_), + synchronization_data_(std::make_shared()), + worker_thread_(&AsyncBatchLogProcessor::DoBackgroundWork, this) +{ + synchronization_data_->is_force_wakeup_background_worker.store(false); + synchronization_data_->is_force_flush_pending.store(false); + synchronization_data_->is_force_flush_notified.store(false); + synchronization_data_->is_shutdown.store(false); + + export_data_storage_->export_ids_flag.resize(max_export_async_, true); + for (size_t i = 1; i <= max_export_async_; i++) + { + export_data_storage_->export_ids.push(i); + } +} + +AsyncBatchLogProcessor::AsyncBatchLogProcessor(std::unique_ptr &&exporter, + const AsyncBatchLogProcessorOptions &options) + : exporter_(std::move(exporter)), + max_queue_size_(options.max_queue_size), + scheduled_delay_millis_(options.schedule_delay_millis), + max_export_batch_size_(options.max_export_batch_size), + max_export_async_(options.max_export_async), + export_data_storage_(std::make_shared()), + buffer_(options.max_queue_size), + synchronization_data_(std::make_shared()), + worker_thread_(&AsyncBatchLogProcessor::DoBackgroundWork, this) +{ + synchronization_data_->is_force_wakeup_background_worker.store(false); + synchronization_data_->is_force_flush_pending.store(false); + synchronization_data_->is_force_flush_notified.store(false); + synchronization_data_->is_shutdown.store(false); + + export_data_storage_->export_ids_flag.resize(max_export_async_, true); + for (int i = 1; i <= max_export_async_; i++) + { + export_data_storage_->export_ids.push(i); + } +} + +std::unique_ptr AsyncBatchLogProcessor::MakeRecordable() noexcept +{ + return exporter_->MakeRecordable(); +} + +void AsyncBatchLogProcessor::OnReceive(std::unique_ptr &&record) noexcept +{ + if (synchronization_data_->is_shutdown.load() == true) + { + return; + } + + if (buffer_.Add(record) == false) + { + return; + } + + // If the queue gets at least half full a preemptive notification is + // sent to the worker thread to start a new export cycle. + size_t buffer_size = buffer_.size(); + if (buffer_size >= max_queue_size_ / 2 || buffer_size >= max_export_batch_size_) + { + // signal the worker thread + synchronization_data_->is_force_wakeup_background_worker.store(true, std::memory_order_release); + synchronization_data_->cv.notify_one(); + } +} + +bool AsyncBatchLogProcessor::ForceFlush(std::chrono::microseconds timeout) noexcept +{ + if (synchronization_data_->is_shutdown.load() == true) + { + return false; + } + + // Now wait for the worker thread to signal back from the Export method + std::unique_lock lk_cv(synchronization_data_->force_flush_cv_m); + + synchronization_data_->is_force_flush_pending.store(true, std::memory_order_release); + auto break_condition = [this]() { + if (synchronization_data_->is_shutdown.load() == true) + { + return true; + } + + // Wake up the worker thread once. + if (synchronization_data_->is_force_flush_pending.load(std::memory_order_acquire)) + { + synchronization_data_->cv.notify_one(); + } + + return synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire); + }; + + // Fix timeout to meet requirement of wait_for + timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( + timeout, std::chrono::microseconds::zero()); + bool result; + if (timeout <= std::chrono::microseconds::zero()) + { + bool wait_result = false; + while (!wait_result) + { + // When is_force_flush_notified.store(true) and force_flush_cv.notify_all() is called + // between is_force_flush_pending.load() and force_flush_cv.wait(). We must not wait + // for ever + wait_result = synchronization_data_->force_flush_cv.wait_for(lk_cv, scheduled_delay_millis_, + break_condition); + } + result = true; + } + else + { + result = synchronization_data_->force_flush_cv.wait_for(lk_cv, timeout, break_condition); + } + + // If it's already signaled, we must wait util notified. + // We use a spin lock here + if (false == + synchronization_data_->is_force_flush_pending.exchange(false, std::memory_order_acq_rel)) + { + for (int retry_waiting_times = 0; + false == synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire); + ++retry_waiting_times) + { + opentelemetry::common::SpinLockMutex::fast_yield(); + if ((retry_waiting_times & 127) == 127) + { + std::this_thread::yield(); + } + } + } + + synchronization_data_->is_force_flush_notified.store(false, std::memory_order_release); + + return result; +} + +void AsyncBatchLogProcessor::DoBackgroundWork() +{ + auto timeout = scheduled_delay_millis_; + + while (true) + { + // Wait for `timeout` milliseconds + std::unique_lock lk(synchronization_data_->cv_m); + synchronization_data_->cv.wait_for(lk, timeout, [this] { + if (synchronization_data_->is_force_wakeup_background_worker.load(std::memory_order_acquire)) + { + return true; + } + + return !buffer_.empty(); + }); + synchronization_data_->is_force_wakeup_background_worker.store(false, + std::memory_order_release); + + if (synchronization_data_->is_shutdown.load() == true) + { + DrainQueue(); + return; + } + + auto start = std::chrono::steady_clock::now(); + Export(); + auto end = std::chrono::steady_clock::now(); + auto duration = std::chrono::duration_cast(end - start); + + // Subtract the duration of this export call from the next `timeout`. + timeout = scheduled_delay_millis_ - duration; + } +} + +void AsyncBatchLogProcessor::Export() +{ + uint64_t current_pending; + uint64_t current_notified; + do + { + std::vector> records_arr; + size_t num_records_to_export; + bool notify_force_flush = + synchronization_data_->is_force_flush_pending.exchange(false, std::memory_order_acq_rel); + if (notify_force_flush) + { + num_records_to_export = buffer_.size(); + } + else + { + num_records_to_export = + buffer_.size() >= max_export_batch_size_ ? max_export_batch_size_ : buffer_.size(); + } + + if (num_records_to_export == 0) + { + NotifyCompletion(notify_force_flush, synchronization_data_); + break; + } + + buffer_.Consume(num_records_to_export, + [&](CircularBufferRange> range) noexcept { + range.ForEach([&](AtomicUniquePtr &ptr) { + std::unique_ptr swap_ptr = std::unique_ptr(nullptr); + ptr.Swap(swap_ptr); + records_arr.push_back(std::unique_ptr(swap_ptr.release())); + return true; + }); + }); + + size_t id = kInvalidExportId; + { + std::unique_lock lock(synchronization_data_->async_export_data_m); + synchronization_data_->async_export_waker.wait_for(lock, scheduled_delay_millis_, [this] { + return export_data_storage_->export_ids.size() > 0; + }); + if (export_data_storage_->export_ids.size() > 0) + { + id = export_data_storage_->export_ids.front(); + export_data_storage_->export_ids.pop(); + export_data_storage_->export_ids_flag[id - 1] = false; + } + } + if (id != kInvalidExportId) + { + std::weak_ptr export_data_watcher = export_data_storage_; + std::weak_ptr synchronization_data_watcher = synchronization_data_; + exporter_->Export( + nostd::span>(records_arr.data(), records_arr.size()), + [notify_force_flush, synchronization_data_watcher, export_data_watcher, + id](sdk::common::ExportResult result) { + // TODO: Print result + if (synchronization_data_watcher.expired()) + { + return true; + } + if (export_data_watcher.expired()) + { + return true; + } + bool is_already_notified = false; + auto synchronization_data = synchronization_data_watcher.lock(); + auto export_data = export_data_watcher.lock(); + { + std::unique_lock lk(synchronization_data->async_export_data_m); + // In case callback is called more than once due to some bug in exporter + // we need to ensure export_ids do not contain duplicate. + if (export_data->export_ids_flag[id - 1] == false) + { + export_data->export_ids.push(id); + export_data->export_ids_flag[id - 1] = true; + } + else + { + is_already_notified = true; + } + } + if (is_already_notified == false) + { + NotifyCompletion(notify_force_flush, synchronization_data); + } + return true; + }); + } + } while (true); +} + +void AsyncBatchLogProcessor::NotifyCompletion( + bool notify_force_flush, + const std::shared_ptr &synchronization_data) +{ + if (!synchronization_data) + { + return; + } + + if (notify_force_flush) + { + synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); + synchronization_data->force_flush_cv.notify_one(); + } + + synchronization_data->async_export_waker.notify_all(); +} + +void AsyncBatchLogProcessor::DrainQueue() +{ + while (true) + { + if (buffer_.empty() && + false == synchronization_data_->is_force_flush_pending.load(std::memory_order_acquire)) + { + break; + } + + Export(); + } +} + +void AsyncBatchLogProcessor::GetWaitAdjustedTime( + std::chrono::microseconds &timeout, + std::chrono::time_point &start_time) +{ + auto end_time = std::chrono::system_clock::now(); + auto offset = std::chrono::duration_cast(end_time - start_time); + start_time = end_time; + timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( + timeout, std::chrono::microseconds::zero()); + if (timeout > offset && timeout > std::chrono::microseconds::zero()) + { + timeout -= offset; + } + else + { + // Some module use zero as indefinite timeout.So we can not reset timeout to zero here + timeout = std::chrono::microseconds(1); + } +} + +bool AsyncBatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcept +{ + auto start_time = std::chrono::system_clock::now(); + + std::lock_guard shutdown_guard{synchronization_data_->shutdown_m}; + bool already_shutdown = synchronization_data_->is_shutdown.exchange(true); + + if (worker_thread_.joinable()) + { + synchronization_data_->is_force_wakeup_background_worker.store(true, std::memory_order_release); + synchronization_data_->cv.notify_one(); + worker_thread_.join(); + } + + GetWaitAdjustedTime(timeout, start_time); + // wait for all async exports to complete and return if timeout reached. + { + std::unique_lock lock(synchronization_data_->async_export_data_m); + synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { + return export_data_storage_->export_ids.size() == max_export_async_; + }); + } + + GetWaitAdjustedTime(timeout, start_time); + // Should only shutdown exporter ONCE. + if (!already_shutdown && exporter_ != nullptr) + { + return exporter_->Shutdown(timeout); + } + + return true; +} + +AsyncBatchLogProcessor::~AsyncBatchLogProcessor() +{ + if (synchronization_data_->is_shutdown.load() == false) + { + Shutdown(); + } +} + +} // namespace logs +} // namespace sdk +OPENTELEMETRY_END_NAMESPACE +# endif +#endif diff --git a/sdk/src/logs/batch_log_processor.cc b/sdk/src/logs/batch_log_processor.cc index aeb9f93024..af2f6cae59 100644 --- a/sdk/src/logs/batch_log_processor.cc +++ b/sdk/src/logs/batch_log_processor.cc @@ -17,22 +17,11 @@ namespace logs BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, const size_t max_queue_size, const std::chrono::milliseconds scheduled_delay_millis, - const size_t max_export_batch_size -# ifdef ENABLE_ASYNC_EXPORT - , - const bool is_export_async, - const size_t max_export_async -# endif - ) + const size_t max_export_batch_size) : exporter_(std::move(exporter)), max_queue_size_(max_queue_size), scheduled_delay_millis_(scheduled_delay_millis), max_export_batch_size_(max_export_batch_size), -# ifdef ENABLE_ASYNC_EXPORT - is_export_async_(is_export_async), - max_export_async_(max_export_async), - export_data_storage_(std::make_shared()), -# endif buffer_(max_queue_size_), synchronization_data_(std::make_shared()), worker_thread_(&BatchLogProcessor::DoBackgroundWork, this) @@ -41,13 +30,6 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); -# ifdef ENABLE_ASYNC_EXPORT - export_data_storage_->export_ids_flag.resize(max_export_async_, true); - for (size_t i = 1; i <= max_export_async_; i++) - { - export_data_storage_->export_ids.push(i); - } -# endif } BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, @@ -56,11 +38,6 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, max_queue_size_(options.max_queue_size), scheduled_delay_millis_(options.schedule_delay_millis), max_export_batch_size_(options.max_export_batch_size), -# ifdef ENABLE_ASYNC_EXPORT - is_export_async_(options.is_export_async), - max_export_async_(options.max_export_async), - export_data_storage_(std::make_shared()), -# endif buffer_(options.max_queue_size), synchronization_data_(std::make_shared()), worker_thread_(&BatchLogProcessor::DoBackgroundWork, this) @@ -69,13 +46,6 @@ BatchLogProcessor::BatchLogProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); -# ifdef ENABLE_ASYNC_EXPORT - export_data_storage_->export_ids_flag.resize(max_export_async_, true); - for (int i = 1; i <= max_export_async_; i++) - { - export_data_storage_->export_ids.push(i); - } -# endif } std::unique_ptr BatchLogProcessor::MakeRecordable() noexcept @@ -247,73 +217,9 @@ void BatchLogProcessor::Export() }); }); -# ifdef ENABLE_ASYNC_EXPORT - if (is_export_async_ == false) - { -# endif - exporter_->Export( - nostd::span>(records_arr.data(), records_arr.size())); - NotifyCompletion(notify_force_flush, synchronization_data_); -# ifdef ENABLE_ASYNC_EXPORT - } - else - { - size_t id = kInvalidExportId; - { - std::unique_lock lock(synchronization_data_->async_export_data_m); - synchronization_data_->async_export_waker.wait_for(lock, scheduled_delay_millis_, [this] { - return export_data_storage_->export_ids.size() > 0; - }); - if (export_data_storage_->export_ids.size() > 0) - { - id = export_data_storage_->export_ids.front(); - export_data_storage_->export_ids.pop(); - export_data_storage_->export_ids_flag[id - 1] = false; - } - } - if (id != kInvalidExportId) - { - std::weak_ptr export_data_watcher = export_data_storage_; - std::weak_ptr synchronization_data_watcher = synchronization_data_; - exporter_->Export( - nostd::span>(records_arr.data(), records_arr.size()), - [notify_force_flush, synchronization_data_watcher, export_data_watcher, - id](sdk::common::ExportResult result) { - // TODO: Print result - if (synchronization_data_watcher.expired()) - { - return true; - } - if (export_data_watcher.expired()) - { - return true; - } - bool is_already_notified = false; - auto synchronization_data = synchronization_data_watcher.lock(); - auto export_data = export_data_watcher.lock(); - { - std::unique_lock lk(synchronization_data->async_export_data_m); - // In case callback is called more than once due to some bug in exporter - // we need to ensure export_ids do not contain duplicate. - if (export_data->export_ids_flag[id - 1] == false) - { - export_data->export_ids.push(id); - export_data->export_ids_flag[id - 1] = true; - } - else - { - is_already_notified = true; - } - } - if (is_already_notified == false) - { - NotifyCompletion(notify_force_flush, synchronization_data); - } - return true; - }); - } - } -# endif + exporter_->Export( + nostd::span>(records_arr.data(), records_arr.size())); + NotifyCompletion(notify_force_flush, synchronization_data_); } while (true); } @@ -331,9 +237,6 @@ void BatchLogProcessor::NotifyCompletion( synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); synchronization_data->force_flush_cv.notify_one(); } -# ifdef ENABLE_ASYNC_EXPORT - synchronization_data->async_export_waker.notify_all(); -# endif } void BatchLogProcessor::DrainQueue() @@ -383,16 +286,7 @@ bool BatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcept synchronization_data_->cv.notify_one(); worker_thread_.join(); } -# ifdef ENABLE_ASYNC_EXPORT - GetWaitAdjustedTime(timeout, start_time); - // wait for all async exports to complete and return if timeout reached. - { - std::unique_lock lock(synchronization_data_->async_export_data_m); - synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { - return export_data_storage_->export_ids.size() == max_export_async_; - }); - } -# endif + GetWaitAdjustedTime(timeout, start_time); // Should only shutdown exporter ONCE. if (!already_shutdown && exporter_ != nullptr) diff --git a/sdk/src/trace/CMakeLists.txt b/sdk/src/trace/CMakeLists.txt index ddef00fb42..bd906b1fab 100644 --- a/sdk/src/trace/CMakeLists.txt +++ b/sdk/src/trace/CMakeLists.txt @@ -5,6 +5,7 @@ add_library( tracer.cc span.cc batch_span_processor.cc + async_batch_span_processor.cc samplers/parent.cc samplers/trace_id_ratio.cc random_id_generator.cc) diff --git a/sdk/src/trace/async_batch_span_processor.cc b/sdk/src/trace/async_batch_span_processor.cc new file mode 100644 index 0000000000..60fa7c370e --- /dev/null +++ b/sdk/src/trace/async_batch_span_processor.cc @@ -0,0 +1,360 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 +#ifdef ENABLE_ASYNC_EXPORT + +# include "opentelemetry/sdk/trace/async_batch_span_processor.h" +# include "opentelemetry/common/spin_lock_mutex.h" + +# include +using opentelemetry::sdk::common::AtomicUniquePtr; +using opentelemetry::sdk::common::CircularBuffer; +using opentelemetry::sdk::common::CircularBufferRange; +using opentelemetry::trace::SpanContext; + +OPENTELEMETRY_BEGIN_NAMESPACE +namespace sdk +{ +namespace trace +{ + +AsyncBatchSpanProcessor::AsyncBatchSpanProcessor(std::unique_ptr &&exporter, + const AsyncBatchSpanProcessorOptions &options) + : exporter_(std::move(exporter)), + max_queue_size_(options.max_queue_size), + schedule_delay_millis_(options.schedule_delay_millis), + max_export_batch_size_(options.max_export_batch_size), + max_export_async_(options.max_export_async), + export_data_storage_(std::make_shared()), + buffer_(max_queue_size_), + synchronization_data_(std::make_shared()), + worker_thread_(&AsyncBatchSpanProcessor::DoBackgroundWork, this) +{ + synchronization_data_->is_force_wakeup_background_worker.store(false); + synchronization_data_->is_force_flush_pending.store(false); + synchronization_data_->is_force_flush_notified.store(false); + synchronization_data_->is_shutdown.store(false); + + export_data_storage_->export_ids_flag.resize(max_export_async_, true); + for (size_t i = 1; i <= max_export_async_; i++) + { + export_data_storage_->export_ids.push(i); + } +} + +std::unique_ptr AsyncBatchSpanProcessor::MakeRecordable() noexcept +{ + return exporter_->MakeRecordable(); +} + +void AsyncBatchSpanProcessor::OnStart(Recordable &, const SpanContext &) noexcept +{ + // no-op +} + +void AsyncBatchSpanProcessor::OnEnd(std::unique_ptr &&span) noexcept +{ + if (synchronization_data_->is_shutdown.load() == true) + { + return; + } + + if (buffer_.Add(span) == false) + { + return; + } + + // If the queue gets at least half full a preemptive notification is + // sent to the worker thread to start a new export cycle. + size_t buffer_size = buffer_.size(); + if (buffer_size >= max_queue_size_ / 2 || buffer_size >= max_export_batch_size_) + { + // signal the worker thread + synchronization_data_->cv.notify_one(); + } +} + +bool AsyncBatchSpanProcessor::ForceFlush(std::chrono::microseconds timeout) noexcept +{ + if (synchronization_data_->is_shutdown.load() == true) + { + return false; + } + + // Now wait for the worker thread to signal back from the Export method + std::unique_lock lk_cv(synchronization_data_->force_flush_cv_m); + + synchronization_data_->is_force_flush_pending.store(true, std::memory_order_release); + auto break_condition = [this]() { + if (synchronization_data_->is_shutdown.load() == true) + { + return true; + } + + // Wake up the worker thread once. + if (synchronization_data_->is_force_flush_pending.load(std::memory_order_acquire)) + { + synchronization_data_->is_force_wakeup_background_worker.store(true, + std::memory_order_release); + synchronization_data_->cv.notify_one(); + } + + return synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire); + }; + + // Fix timeout to meet requirement of wait_for + timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( + timeout, std::chrono::microseconds::zero()); + bool result; + if (timeout <= std::chrono::microseconds::zero()) + { + bool wait_result = false; + while (!wait_result) + { + // When is_force_flush_notified.store(true) and force_flush_cv.notify_all() is called + // between is_force_flush_pending.load() and force_flush_cv.wait(). We must not wait + // for ever + wait_result = synchronization_data_->force_flush_cv.wait_for(lk_cv, schedule_delay_millis_, + break_condition); + } + result = true; + } + else + { + result = synchronization_data_->force_flush_cv.wait_for(lk_cv, timeout, break_condition); + } + + // If it will be already signaled, we must wait util notified. + // We use a spin lock here + if (false == + synchronization_data_->is_force_flush_pending.exchange(false, std::memory_order_acq_rel)) + { + for (int retry_waiting_times = 0; + false == synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire); + ++retry_waiting_times) + { + opentelemetry::common::SpinLockMutex::fast_yield(); + if ((retry_waiting_times & 127) == 127) + { + std::this_thread::yield(); + } + } + } + synchronization_data_->is_force_flush_notified.store(false, std::memory_order_release); + + return result; +} + +void AsyncBatchSpanProcessor::DoBackgroundWork() +{ + auto timeout = schedule_delay_millis_; + + while (true) + { + // Wait for `timeout` milliseconds + std::unique_lock lk(synchronization_data_->cv_m); + synchronization_data_->cv.wait_for(lk, timeout, [this] { + if (synchronization_data_->is_force_wakeup_background_worker.load(std::memory_order_acquire)) + { + return true; + } + + return !buffer_.empty(); + }); + synchronization_data_->is_force_wakeup_background_worker.store(false, + std::memory_order_release); + + if (synchronization_data_->is_shutdown.load() == true) + { + DrainQueue(); + return; + } + + auto start = std::chrono::steady_clock::now(); + Export(); + auto end = std::chrono::steady_clock::now(); + auto duration = std::chrono::duration_cast(end - start); + + // Subtract the duration of this export call from the next `timeout`. + timeout = schedule_delay_millis_ - duration; + } +} + +void AsyncBatchSpanProcessor::Export() +{ + do + { + std::vector> spans_arr; + size_t num_records_to_export; + bool notify_force_flush = + synchronization_data_->is_force_flush_pending.exchange(false, std::memory_order_acq_rel); + if (notify_force_flush) + { + num_records_to_export = buffer_.size(); + } + else + { + num_records_to_export = + buffer_.size() >= max_export_batch_size_ ? max_export_batch_size_ : buffer_.size(); + } + + if (num_records_to_export == 0) + { + NotifyCompletion(notify_force_flush, synchronization_data_); + break; + } + buffer_.Consume(num_records_to_export, + [&](CircularBufferRange> range) noexcept { + range.ForEach([&](AtomicUniquePtr &ptr) { + std::unique_ptr swap_ptr = std::unique_ptr(nullptr); + ptr.Swap(swap_ptr); + spans_arr.push_back(std::unique_ptr(swap_ptr.release())); + return true; + }); + }); + + size_t id = kInvalidExportId; + { + std::unique_lock lock(synchronization_data_->async_export_data_m); + synchronization_data_->async_export_waker.wait_for(lock, schedule_delay_millis_, [this] { + return export_data_storage_->export_ids.size() > 0; + }); + if (export_data_storage_->export_ids.size() > 0) + { + id = export_data_storage_->export_ids.front(); + export_data_storage_->export_ids.pop(); + export_data_storage_->export_ids_flag[id - 1] = false; + } + } + if (id != kInvalidExportId) + { + std::weak_ptr export_data_watcher = export_data_storage_; + + std::weak_ptr synchronization_data_watcher = synchronization_data_; + exporter_->Export( + nostd::span>(spans_arr.data(), spans_arr.size()), + [notify_force_flush, synchronization_data_watcher, export_data_watcher, + id](sdk::common::ExportResult result) { + // TODO: Print result + if (synchronization_data_watcher.expired()) + { + return true; + } + + if (export_data_watcher.expired()) + { + return true; + } + + auto synchronization_data = synchronization_data_watcher.lock(); + auto export_data = export_data_watcher.lock(); + { + std::unique_lock lk(synchronization_data->async_export_data_m); + if (export_data->export_ids_flag[id - 1] == false) + { + export_data->export_ids.push(id); + export_data->export_ids_flag[id - 1] = true; + } + } + NotifyCompletion(notify_force_flush, synchronization_data); + return true; + }); + } + } while (true); +} + +void AsyncBatchSpanProcessor::NotifyCompletion( + bool notify_force_flush, + const std::shared_ptr &synchronization_data) +{ + if (!synchronization_data) + { + return; + } + + if (notify_force_flush) + { + synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); + synchronization_data->force_flush_cv.notify_one(); + } + + synchronization_data->async_export_waker.notify_all(); +} + +void AsyncBatchSpanProcessor::DrainQueue() +{ + while (true) + { + if (buffer_.empty() && + false == synchronization_data_->is_force_flush_pending.load(std::memory_order_acquire)) + { + break; + } + + Export(); + } +} + +void AsyncBatchSpanProcessor::GetWaitAdjustedTime( + std::chrono::microseconds &timeout, + std::chrono::time_point &start_time) +{ + auto end_time = std::chrono::system_clock::now(); + auto offset = std::chrono::duration_cast(end_time - start_time); + start_time = end_time; + timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( + timeout, std::chrono::microseconds::zero()); + if (timeout > offset && timeout > std::chrono::microseconds::zero()) + { + timeout -= offset; + } + else + { + // Some module use zero as indefinite timeout.So we can not reset timeout to zero here + timeout = std::chrono::microseconds(1); + } +} + +bool AsyncBatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexcept +{ + auto start_time = std::chrono::system_clock::now(); + std::lock_guard shutdown_guard{synchronization_data_->shutdown_m}; + bool already_shutdown = synchronization_data_->is_shutdown.exchange(true); + + if (worker_thread_.joinable()) + { + synchronization_data_->is_force_wakeup_background_worker.store(true, std::memory_order_release); + synchronization_data_->cv.notify_one(); + worker_thread_.join(); + } + + GetWaitAdjustedTime(timeout, start_time); + // wait for all async exports to complete and return if timeout reached. + { + std::unique_lock lock(synchronization_data_->async_export_data_m); + synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { + return export_data_storage_->export_ids.size() == max_export_async_; + }); + } + + GetWaitAdjustedTime(timeout, start_time); + // Should only shutdown exporter ONCE. + if (!already_shutdown && exporter_ != nullptr) + { + return exporter_->Shutdown(timeout); + } + + return true; +} + +AsyncBatchSpanProcessor::~AsyncBatchSpanProcessor() +{ + if (synchronization_data_->is_shutdown.load() == false) + { + Shutdown(); + } +} + +} // namespace trace +} // namespace sdk +OPENTELEMETRY_END_NAMESPACE +#endif diff --git a/sdk/src/trace/batch_span_processor.cc b/sdk/src/trace/batch_span_processor.cc index 89661bfa82..4609eae95f 100644 --- a/sdk/src/trace/batch_span_processor.cc +++ b/sdk/src/trace/batch_span_processor.cc @@ -22,11 +22,6 @@ BatchSpanProcessor::BatchSpanProcessor(std::unique_ptr &&exporter, max_queue_size_(options.max_queue_size), schedule_delay_millis_(options.schedule_delay_millis), max_export_batch_size_(options.max_export_batch_size), -#ifdef ENABLE_ASYNC_EXPORT - is_export_async_(options.is_export_async), - max_export_async_(options.max_export_async), - export_data_storage_(std::make_shared()), -#endif buffer_(max_queue_size_), synchronization_data_(std::make_shared()), worker_thread_(&BatchSpanProcessor::DoBackgroundWork, this) @@ -35,14 +30,6 @@ BatchSpanProcessor::BatchSpanProcessor(std::unique_ptr &&exporter, synchronization_data_->is_force_flush_pending.store(false); synchronization_data_->is_force_flush_notified.store(false); synchronization_data_->is_shutdown.store(false); - -#ifdef ENABLE_ASYNC_EXPORT - export_data_storage_->export_ids_flag.resize(max_export_async_, true); - for (size_t i = 1; i <= max_export_async_; i++) - { - export_data_storage_->export_ids.push(i); - } -#endif } std::unique_ptr BatchSpanProcessor::MakeRecordable() noexcept @@ -216,66 +203,8 @@ void BatchSpanProcessor::Export() }); }); -#ifdef ENABLE_ASYNC_EXPORT - if (is_export_async_ == false) - { -#endif - exporter_->Export( - nostd::span>(spans_arr.data(), spans_arr.size())); - NotifyCompletion(notify_force_flush, synchronization_data_); -#ifdef ENABLE_ASYNC_EXPORT - } - else - { - size_t id = kInvalidExportId; - { - std::unique_lock lock(synchronization_data_->async_export_data_m); - synchronization_data_->async_export_waker.wait_for(lock, schedule_delay_millis_, [this] { - return export_data_storage_->export_ids.size() > 0; - }); - if (export_data_storage_->export_ids.size() > 0) - { - id = export_data_storage_->export_ids.front(); - export_data_storage_->export_ids.pop(); - export_data_storage_->export_ids_flag[id - 1] = false; - } - } - if (id != kInvalidExportId) - { - std::weak_ptr export_data_watcher = export_data_storage_; - - std::weak_ptr synchronization_data_watcher = synchronization_data_; - exporter_->Export( - nostd::span>(spans_arr.data(), spans_arr.size()), - [notify_force_flush, synchronization_data_watcher, export_data_watcher, - id](sdk::common::ExportResult result) { - // TODO: Print result - if (synchronization_data_watcher.expired()) - { - return true; - } - - if (export_data_watcher.expired()) - { - return true; - } - - auto synchronization_data = synchronization_data_watcher.lock(); - auto export_data = export_data_watcher.lock(); - { - std::unique_lock lk(synchronization_data->async_export_data_m); - if (export_data->export_ids_flag[id - 1] == false) - { - export_data->export_ids.push(id); - export_data->export_ids_flag[id - 1] = true; - } - } - NotifyCompletion(notify_force_flush, synchronization_data); - return true; - }); - } - } -#endif + exporter_->Export(nostd::span>(spans_arr.data(), spans_arr.size())); + NotifyCompletion(notify_force_flush, synchronization_data_); } while (true); } @@ -293,9 +222,6 @@ void BatchSpanProcessor::NotifyCompletion( synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); synchronization_data->force_flush_cv.notify_one(); } -#ifdef ENABLE_ASYNC_EXPORT - synchronization_data->async_export_waker.notify_all(); -#endif } void BatchSpanProcessor::DrainQueue() @@ -345,17 +271,6 @@ bool BatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexcept worker_thread_.join(); } -#ifdef ENABLE_ASYNC_EXPORT - GetWaitAdjustedTime(timeout, start_time); - // wait for all async exports to complete and return if timeout reached. - { - std::unique_lock lock(synchronization_data_->async_export_data_m); - synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { - return export_data_storage_->export_ids.size() == max_export_async_; - }); - } -#endif - GetWaitAdjustedTime(timeout, start_time); // Should only shutdown exporter ONCE. if (!already_shutdown && exporter_ != nullptr) diff --git a/sdk/test/logs/CMakeLists.txt b/sdk/test/logs/CMakeLists.txt index 84b865d226..550b48edd8 100644 --- a/sdk/test/logs/CMakeLists.txt +++ b/sdk/test/logs/CMakeLists.txt @@ -1,5 +1,8 @@ -foreach(testname logger_provider_sdk_test logger_sdk_test log_record_test - simple_log_processor_test batch_log_processor_test) +foreach( + testname + logger_provider_sdk_test logger_sdk_test log_record_test + simple_log_processor_test batch_log_processor_test + async_batch_log_processor_test) add_executable(${testname} "${testname}.cc") target_link_libraries(${testname} ${GTEST_BOTH_LIBRARIES} ${CMAKE_THREAD_LIBS_INIT} opentelemetry_logs) diff --git a/sdk/test/logs/async_batch_log_processor_test.cc b/sdk/test/logs/async_batch_log_processor_test.cc new file mode 100644 index 0000000000..1a4f024217 --- /dev/null +++ b/sdk/test/logs/async_batch_log_processor_test.cc @@ -0,0 +1,372 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 +#ifndef ENABLE_ASYNC_EXPORT +# include +TEST(AsyncBatchLogProcessor, DummyTest) +{ + // For linking +} +#endif + +#ifdef ENABLE_LOGS_PREVIEW +# ifdef ENABLE_ASYNC_EXPORT + +# include "opentelemetry/sdk/logs/async_batch_log_processor.h" +# include "opentelemetry/sdk/logs/exporter.h" +# include "opentelemetry/sdk/logs/log_record.h" + +# include +# include +# include +# include +# include + +using namespace opentelemetry::sdk::logs; +using namespace opentelemetry::sdk::common; + +/** + * A sample log exporter + * for testing the batch log processor + */ +class MockLogExporter final : public LogExporter +{ +public: + MockLogExporter(std::shared_ptr>> logs_received, + std::shared_ptr> is_shutdown, + std::shared_ptr> is_export_completed, + const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0), + int callback_count = 1) + : logs_received_(logs_received), + is_shutdown_(is_shutdown), + is_export_completed_(is_export_completed), + export_delay_(export_delay), + callback_count_(callback_count) + {} + + std::unique_ptr MakeRecordable() noexcept + { + return std::unique_ptr(new LogRecord()); + } + + // Export method stores the logs received into a shared list of record names + ExportResult Export( + const opentelemetry::nostd::span> &records) noexcept override + { + *is_export_completed_ = false; // Meant exclusively to test scheduled_delay_millis + + for (auto &record : records) + { + auto log = std::unique_ptr(static_cast(record.release())); + if (log != nullptr) + { + logs_received_->push_back(std::move(log)); + } + } + + *is_export_completed_ = true; + return ExportResult::kSuccess; + } + + void Export(const opentelemetry::nostd::span> &records, + std::function + &&result_callback) noexcept override + { + // We should keep the order of test records + auto result = Export(records); + async_threads_.emplace_back(std::make_shared( + [this, + result](std::function &&result_callback) { + for (int i = 0; i < callback_count_; i++) + { + result_callback(result); + } + }, + std::move(result_callback))); + } + + // toggles the boolean flag marking this exporter as shut down + bool Shutdown( + std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override + { + while (!async_threads_.empty()) + { + std::list> async_threads; + async_threads.swap(async_threads_); + for (auto &async_thread : async_threads) + { + if (async_thread && async_thread->joinable()) + { + async_thread->join(); + } + } + } + *is_shutdown_ = true; + return true; + } + +private: + std::shared_ptr>> logs_received_; + std::shared_ptr> is_shutdown_; + std::shared_ptr> is_export_completed_; + const std::chrono::milliseconds export_delay_; + std::list> async_threads_; + int callback_count_; +}; + +/** + * A fixture class for testing the BatchLogProcessor class that uses the TestExporter defined above. + */ +class AsyncBatchLogProcessorTest : public testing::Test // ::testing::Test +{ +public: + // returns a batch log processor that received a batch of log records, a shared pointer to a + // is_shutdown flag, and the processor configuration options (default if unspecified) + std::shared_ptr GetMockProcessor( + std::shared_ptr>> logs_received, + std::shared_ptr> is_shutdown, + std::shared_ptr> is_export_completed = + std::shared_ptr>(new std::atomic(false)), + const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0), + const std::chrono::milliseconds scheduled_delay_millis = std::chrono::milliseconds(5000), + const size_t max_queue_size = 2048, + const size_t max_export_batch_size = 512, + const size_t max_export_async = 8, + int callback_count = 1) + { + return std::shared_ptr(new AsyncBatchLogProcessor( + std::unique_ptr(new MockLogExporter( + logs_received, is_shutdown, is_export_completed, export_delay, callback_count)), + max_queue_size, scheduled_delay_millis, max_export_batch_size, max_export_async)); + } +}; + +TEST_F(AsyncBatchLogProcessorTest, TestAsyncShutdown) +{ + // initialize a batch log processor with the test exporter + std::shared_ptr>> logs_received( + new std::vector>); + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr> is_export_completed(new std::atomic(false)); + + const std::chrono::milliseconds export_delay(0); + const std::chrono::milliseconds scheduled_delay_millis(5000); + const size_t max_export_batch_size = 512; + const size_t max_queue_size = 2048; + const bool is_export_async = true; + const size_t max_export_async = 5; + + auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, + export_delay, scheduled_delay_millis, max_queue_size, + max_export_batch_size, is_export_async, max_export_async); + + // Create a few test log records and send them to the processor + const int num_logs = 2048; + + for (int i = 0; i < num_logs; ++i) + { + auto log = batch_processor->MakeRecordable(); + log->SetName("Log" + std::to_string(i)); + batch_processor->OnReceive(std::move(log)); + } + + // Test that shutting down the processor will first wait for the + // current batch of logs to be sent to the log exporter + // by checking the number of logs sent and the names of the logs sent + EXPECT_EQ(true, batch_processor->Shutdown()); + // It's safe to shutdown again + EXPECT_TRUE(batch_processor->Shutdown()); + + EXPECT_EQ(num_logs, logs_received->size()); + + // Assume logs are received by exporter in same order as sent by processor + for (int i = 0; i < num_logs; ++i) + { + EXPECT_EQ("Log" + std::to_string(i), logs_received->at(i)->GetName()); + } + + // Also check that the processor is shut down at the end + EXPECT_TRUE(is_shutdown->load()); +} + +TEST_F(AsyncBatchLogProcessorTest, TestAsyncShutdownNoCallback) +{ + // initialize a batch log processor with the test exporter + std::shared_ptr>> logs_received( + new std::vector>); + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr> is_export_completed(new std::atomic(false)); + + const std::chrono::milliseconds export_delay(0); + const std::chrono::milliseconds scheduled_delay_millis(5000); + const size_t max_export_batch_size = 512; + const size_t max_queue_size = 2048; + const bool is_export_async = true; + const size_t max_export_async = 5; + + auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, + export_delay, scheduled_delay_millis, max_queue_size, + max_export_batch_size, max_export_async, 0); + + // Create a few test log records and send them to the processor + const int num_logs = 2048; + + for (int i = 0; i < num_logs; ++i) + { + auto log = batch_processor->MakeRecordable(); + log->SetName("Log" + std::to_string(i)); + batch_processor->OnReceive(std::move(log)); + } + + EXPECT_EQ(true, batch_processor->Shutdown(std::chrono::milliseconds(5000))); + // It's safe to shutdown again + EXPECT_TRUE(batch_processor->Shutdown()); + + // Also check that the processor is shut down at the end + EXPECT_TRUE(is_shutdown->load()); +} + +TEST_F(AsyncBatchLogProcessorTest, TestAsyncForceFlush) +{ + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr>> logs_received( + new std::vector>); + std::shared_ptr> is_export_completed(new std::atomic(false)); + + const std::chrono::milliseconds export_delay(0); + const std::chrono::milliseconds scheduled_delay_millis(5000); + const size_t max_export_batch_size = 512; + const size_t max_queue_size = 2048; + const bool is_export_async = true; + + auto batch_processor = + GetMockProcessor(logs_received, is_shutdown, is_export_completed, export_delay, + scheduled_delay_millis, max_queue_size, max_export_batch_size); + + const int num_logs = 2048; + + for (int i = 0; i < num_logs; ++i) + { + auto log = batch_processor->MakeRecordable(); + log->SetName("Log" + std::to_string(i)); + batch_processor->OnReceive(std::move(log)); + } + + EXPECT_TRUE(batch_processor->ForceFlush()); + + EXPECT_EQ(num_logs, logs_received->size()); + for (int i = 0; i < num_logs; ++i) + { + EXPECT_EQ("Log" + std::to_string(i), logs_received->at(i)->GetName()); + } + + // Create some more logs to make sure that the processor still works + for (int i = 0; i < num_logs; ++i) + { + auto log = batch_processor->MakeRecordable(); + log->SetName("Log" + std::to_string(i)); + batch_processor->OnReceive(std::move(log)); + } + + EXPECT_TRUE(batch_processor->ForceFlush()); + + EXPECT_EQ(num_logs * 2, logs_received->size()); + for (int i = 0; i < num_logs * 2; ++i) + { + EXPECT_EQ("Log" + std::to_string(i % num_logs), logs_received->at(i)->GetName()); + } +} + +TEST_F(AsyncBatchLogProcessorTest, TestManyLogsLoss) +{ + /* Test that when exporting more than max_queue_size logs, some are most likely lost*/ + + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr>> logs_received( + new std::vector>); + + const int max_queue_size = 4096; + + auto batch_processor = GetMockProcessor(logs_received, is_shutdown); + + // Create max_queue_size log records + for (int i = 0; i < max_queue_size; ++i) + { + auto log = batch_processor->MakeRecordable(); + log->SetName("Log" + std::to_string(i)); + batch_processor->OnReceive(std::move(log)); + } + + EXPECT_TRUE(batch_processor->ForceFlush()); + + // Log should be exported by now + EXPECT_GE(max_queue_size, logs_received->size()); +} + +TEST_F(AsyncBatchLogProcessorTest, TestManyLogsLossLess) +{ + /* Test that no logs are lost when sending max_queue_size logs */ + + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr>> logs_received( + new std::vector>); + auto batch_processor = GetMockProcessor(logs_received, is_shutdown); + + const int num_logs = 2048; + + for (int i = 0; i < num_logs; ++i) + { + auto log = batch_processor->MakeRecordable(); + log->SetName("Log" + std::to_string(i)); + batch_processor->OnReceive(std::move(log)); + } + + EXPECT_TRUE(batch_processor->ForceFlush()); + + EXPECT_EQ(num_logs, logs_received->size()); + for (int i = 0; i < num_logs; ++i) + { + EXPECT_EQ("Log" + std::to_string(i), logs_received->at(i)->GetName()); + } +} + +TEST_F(AsyncBatchLogProcessorTest, TestScheduledDelayMillis) +{ + /* Test that max_export_batch_size logs are exported every scheduled_delay_millis + seconds */ + + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr> is_export_completed(new std::atomic(false)); + std::shared_ptr>> logs_received( + new std::vector>); + + const std::chrono::milliseconds export_delay(0); + const std::chrono::milliseconds scheduled_delay_millis(2000); + const size_t max_export_batch_size = 512; + + auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, + export_delay, scheduled_delay_millis); + + for (std::size_t i = 0; i < max_export_batch_size; ++i) + { + auto log = batch_processor->MakeRecordable(); + log->SetName("Log" + std::to_string(i)); + batch_processor->OnReceive(std::move(log)); + } + // Sleep for scheduled_delay_millis milliseconds + std::this_thread::sleep_for(scheduled_delay_millis); + + // small delay to give time to export, which is being performed + // asynchronously by the worker thread (this thread will not + // forcibly join() the main thread unless processor's shutdown() is called). + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + + // Logs should be exported by now + EXPECT_TRUE(is_export_completed->load()); + EXPECT_EQ(max_export_batch_size, logs_received->size()); + for (size_t i = 0; i < max_export_batch_size; ++i) + { + EXPECT_EQ("Log" + std::to_string(i), logs_received->at(i)->GetName()); + } +} +# endif +#endif diff --git a/sdk/test/logs/batch_log_processor_test.cc b/sdk/test/logs/batch_log_processor_test.cc index d3980f802a..5e4e0f852b 100644 --- a/sdk/test/logs/batch_log_processor_test.cc +++ b/sdk/test/logs/batch_log_processor_test.cc @@ -26,20 +26,11 @@ class MockLogExporter final : public LogExporter MockLogExporter(std::shared_ptr>> logs_received, std::shared_ptr> is_shutdown, std::shared_ptr> is_export_completed, - const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0) -# ifdef ENABLE_ASYNC_EXPORT - , - int callback_count = 1 -# endif - ) + const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0)) : logs_received_(logs_received), is_shutdown_(is_shutdown), is_export_completed_(is_export_completed), export_delay_(export_delay) -# ifdef ENABLE_ASYNC_EXPORT - , - callback_count_(callback_count) -# endif {} std::unique_ptr MakeRecordable() noexcept @@ -73,15 +64,7 @@ class MockLogExporter final : public LogExporter { // We should keep the order of test records auto result = Export(records); - async_threads_.emplace_back(std::make_shared( - [this, - result](std::function &&result_callback) { - for (int i = 0; i < callback_count_; i++) - { - result_callback(result); - } - }, - std::move(result_callback))); + result_callback(result); } # endif @@ -89,18 +72,6 @@ class MockLogExporter final : public LogExporter bool Shutdown( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override { - while (!async_threads_.empty()) - { - std::list> async_threads; - async_threads.swap(async_threads_); - for (auto &async_thread : async_threads) - { - if (async_thread && async_thread->joinable()) - { - async_thread->join(); - } - } - } *is_shutdown_ = true; return true; } @@ -110,10 +81,6 @@ class MockLogExporter final : public LogExporter std::shared_ptr> is_shutdown_; std::shared_ptr> is_export_completed_; const std::chrono::milliseconds export_delay_; - std::list> async_threads_; -# ifdef ENABLE_ASYNC_EXPORT - int callback_count_; -# endif }; /** @@ -132,29 +99,12 @@ class BatchLogProcessorTest : public testing::Test // ::testing::Test const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0), const std::chrono::milliseconds scheduled_delay_millis = std::chrono::milliseconds(5000), const size_t max_queue_size = 2048, - const size_t max_export_batch_size = 512 -# ifdef ENABLE_ASYNC_EXPORT - , - const bool is_export_async = false, - const size_t max_export_async = 8, - int callback_count = 1 -# endif - ) + const size_t max_export_batch_size = 512) { - return std::shared_ptr(new BatchLogProcessor( - std::unique_ptr(new MockLogExporter(logs_received, is_shutdown, - is_export_completed, export_delay -# ifdef ENABLE_ASYNC_EXPORT - , - callback_count -# endif - )), - max_queue_size, scheduled_delay_millis, max_export_batch_size -# ifdef ENABLE_ASYNC_EXPORT - , - is_export_async, max_export_async -# endif - )); + return std::shared_ptr( + new BatchLogProcessor(std::unique_ptr(new MockLogExporter( + logs_received, is_shutdown, is_export_completed, export_delay)), + max_queue_size, scheduled_delay_millis, max_export_batch_size)); } }; @@ -196,93 +146,6 @@ TEST_F(BatchLogProcessorTest, TestShutdown) EXPECT_TRUE(is_shutdown->load()); } -# ifdef ENABLE_ASYNC_EXPORT -TEST_F(BatchLogProcessorTest, TestAsyncShutdown) -{ - // initialize a batch log processor with the test exporter - std::shared_ptr>> logs_received( - new std::vector>); - std::shared_ptr> is_shutdown(new std::atomic(false)); - std::shared_ptr> is_export_completed(new std::atomic(false)); - - const std::chrono::milliseconds export_delay(0); - const std::chrono::milliseconds scheduled_delay_millis(5000); - const size_t max_export_batch_size = 512; - const size_t max_queue_size = 2048; - const bool is_export_async = true; - const size_t max_export_async = 5; - - auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, - export_delay, scheduled_delay_millis, max_queue_size, - max_export_batch_size, is_export_async, max_export_async); - - // Create a few test log records and send them to the processor - const int num_logs = 2048; - - for (int i = 0; i < num_logs; ++i) - { - auto log = batch_processor->MakeRecordable(); - log->SetName("Log" + std::to_string(i)); - batch_processor->OnReceive(std::move(log)); - } - - // Test that shutting down the processor will first wait for the - // current batch of logs to be sent to the log exporter - // by checking the number of logs sent and the names of the logs sent - EXPECT_EQ(true, batch_processor->Shutdown()); - // It's safe to shutdown again - EXPECT_TRUE(batch_processor->Shutdown()); - - EXPECT_EQ(num_logs, logs_received->size()); - - // Assume logs are received by exporter in same order as sent by processor - for (int i = 0; i < num_logs; ++i) - { - EXPECT_EQ("Log" + std::to_string(i), logs_received->at(i)->GetName()); - } - - // Also check that the processor is shut down at the end - EXPECT_TRUE(is_shutdown->load()); -} - -TEST_F(BatchLogProcessorTest, TestAsyncShutdownNoCallback) -{ - // initialize a batch log processor with the test exporter - std::shared_ptr>> logs_received( - new std::vector>); - std::shared_ptr> is_shutdown(new std::atomic(false)); - std::shared_ptr> is_export_completed(new std::atomic(false)); - - const std::chrono::milliseconds export_delay(0); - const std::chrono::milliseconds scheduled_delay_millis(5000); - const size_t max_export_batch_size = 512; - const size_t max_queue_size = 2048; - const bool is_export_async = true; - const size_t max_export_async = 5; - - auto batch_processor = GetMockProcessor( - logs_received, is_shutdown, is_export_completed, export_delay, scheduled_delay_millis, - max_queue_size, max_export_batch_size, is_export_async, max_export_async, 0); - - // Create a few test log records and send them to the processor - const int num_logs = 2048; - - for (int i = 0; i < num_logs; ++i) - { - auto log = batch_processor->MakeRecordable(); - log->SetName("Log" + std::to_string(i)); - batch_processor->OnReceive(std::move(log)); - } - - EXPECT_EQ(true, batch_processor->Shutdown(std::chrono::milliseconds(5000))); - // It's safe to shutdown again - EXPECT_TRUE(batch_processor->Shutdown()); - - // Also check that the processor is shut down at the end - EXPECT_TRUE(is_shutdown->load()); -} -# endif - TEST_F(BatchLogProcessorTest, TestForceFlush) { std::shared_ptr> is_shutdown(new std::atomic(false)); @@ -324,59 +187,6 @@ TEST_F(BatchLogProcessorTest, TestForceFlush) } } -# ifdef ENABLE_ASYNC_EXPORT -TEST_F(BatchLogProcessorTest, TestAsyncForceFlush) -{ - std::shared_ptr> is_shutdown(new std::atomic(false)); - std::shared_ptr>> logs_received( - new std::vector>); - std::shared_ptr> is_export_completed(new std::atomic(false)); - - const std::chrono::milliseconds export_delay(0); - const std::chrono::milliseconds scheduled_delay_millis(5000); - const size_t max_export_batch_size = 512; - const size_t max_queue_size = 2048; - const bool is_export_async = true; - - auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, - export_delay, scheduled_delay_millis, max_queue_size, - max_export_batch_size, is_export_async); - - const int num_logs = 2048; - - for (int i = 0; i < num_logs; ++i) - { - auto log = batch_processor->MakeRecordable(); - log->SetName("Log" + std::to_string(i)); - batch_processor->OnReceive(std::move(log)); - } - - EXPECT_TRUE(batch_processor->ForceFlush()); - - EXPECT_EQ(num_logs, logs_received->size()); - for (int i = 0; i < num_logs; ++i) - { - EXPECT_EQ("Log" + std::to_string(i), logs_received->at(i)->GetName()); - } - - // Create some more logs to make sure that the processor still works - for (int i = 0; i < num_logs; ++i) - { - auto log = batch_processor->MakeRecordable(); - log->SetName("Log" + std::to_string(i)); - batch_processor->OnReceive(std::move(log)); - } - - EXPECT_TRUE(batch_processor->ForceFlush()); - - EXPECT_EQ(num_logs * 2, logs_received->size()); - for (int i = 0; i < num_logs * 2; ++i) - { - EXPECT_EQ("Log" + std::to_string(i % num_logs), logs_received->at(i)->GetName()); - } -} -# endif - TEST_F(BatchLogProcessorTest, TestManyLogsLoss) { /* Test that when exporting more than max_queue_size logs, some are most likely lost*/ diff --git a/sdk/test/trace/CMakeLists.txt b/sdk/test/trace/CMakeLists.txt index b02ff705fa..8e9402625b 100644 --- a/sdk/test/trace/CMakeLists.txt +++ b/sdk/test/trace/CMakeLists.txt @@ -8,7 +8,8 @@ foreach( always_on_sampler_test parent_sampler_test trace_id_ratio_sampler_test - batch_span_processor_test) + batch_span_processor_test + async_batch_span_processor_test) add_executable(${testname} "${testname}.cc") target_link_libraries( ${testname} diff --git a/sdk/test/trace/async_batch_span_processor_test.cc b/sdk/test/trace/async_batch_span_processor_test.cc new file mode 100644 index 0000000000..1ac28c5bc9 --- /dev/null +++ b/sdk/test/trace/async_batch_span_processor_test.cc @@ -0,0 +1,375 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 +#ifndef ENABLE_ASYNC_EXPORT +# include +TEST(AsyncBatchSpanProcessor, DummyTest) +{ + // For linking +} +#endif + +#ifdef ENABLE_ASYNC_EXPORT + +# include "opentelemetry/sdk/trace/async_batch_span_processor.h" +# include "opentelemetry/sdk/trace/span_data.h" +# include "opentelemetry/sdk/trace/tracer.h" + +# include +# include +# include +# include +# include + +OPENTELEMETRY_BEGIN_NAMESPACE + +/** + * Returns a mock span exporter meant exclusively for testing only + */ +class MockSpanExporter final : public sdk::trace::SpanExporter +{ +public: + MockSpanExporter( + std::shared_ptr>> spans_received, + std::shared_ptr> is_shutdown, + std::shared_ptr> is_export_completed = + std::shared_ptr>(new std::atomic(false)), + const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0), + int callback_count = 1) noexcept + : spans_received_(spans_received), + is_shutdown_(is_shutdown), + is_export_completed_(is_export_completed), + export_delay_(export_delay), + callback_count_(callback_count) + {} + + std::unique_ptr MakeRecordable() noexcept override + { + return std::unique_ptr(new sdk::trace::SpanData); + } + + sdk::common::ExportResult Export( + const nostd::span> &recordables) noexcept override + { + *is_export_completed_ = false; + + std::this_thread::sleep_for(export_delay_); + + for (auto &recordable : recordables) + { + auto span = std::unique_ptr( + static_cast(recordable.release())); + + if (span != nullptr) + { + spans_received_->push_back(std::move(span)); + } + } + + *is_export_completed_ = true; + return sdk::common::ExportResult::kSuccess; + } + + void Export(const nostd::span> &records, + std::function + &&result_callback) noexcept override + { + // We should keep the order of test records + auto result = Export(records); + async_threads_.emplace_back(std::make_shared( + [this, + result](std::function &&result_callback) { + for (int i = 0; i < callback_count_; i++) + { + result_callback(result); + } + }, + std::move(result_callback))); + } + + bool Shutdown( + std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override + { + while (!async_threads_.empty()) + { + std::list> async_threads; + async_threads.swap(async_threads_); + for (auto &async_thread : async_threads) + { + if (async_thread && async_thread->joinable()) + { + async_thread->join(); + } + } + } + *is_shutdown_ = true; + return true; + } + + bool IsExportCompleted() { return is_export_completed_->load(); } + +private: + std::shared_ptr>> spans_received_; + std::shared_ptr> is_shutdown_; + std::shared_ptr> is_export_completed_; + // Meant exclusively to test force flush timeout + const std::chrono::milliseconds export_delay_; + std::list> async_threads_; + int callback_count_; +}; + +/** + * Fixture Class + */ +class AsyncBatchSpanProcessorTestPeer : public testing::Test +{ +public: + std::unique_ptr>> GetTestSpans( + std::shared_ptr processor, + const int num_spans) + { + std::unique_ptr>> test_spans( + new std::vector>); + + for (int i = 0; i < num_spans; ++i) + { + test_spans->push_back(processor->MakeRecordable()); + static_cast(test_spans->at(i).get()) + ->SetName("Span " + std::to_string(i)); + } + + return test_spans; + } +}; + +/* ################################## TESTS ############################################ */ + +TEST_F(AsyncBatchSpanProcessorTestPeer, TestAsyncShutdown) +{ + std::shared_ptr>> spans_received( + new std::vector>); + std::shared_ptr> is_shutdown(new std::atomic(false)); + + sdk::trace::AsyncBatchSpanProcessorOptions options{}; + options.max_export_async = 5; + + auto batch_processor = + std::shared_ptr(new sdk::trace::AsyncBatchSpanProcessor( + std::unique_ptr(new MockSpanExporter(spans_received, is_shutdown)), + options)); + const int num_spans = 2048; + + auto test_spans = GetTestSpans(batch_processor, num_spans); + + for (int i = 0; i < num_spans; ++i) + { + batch_processor->OnEnd(std::move(test_spans->at(i))); + } + + EXPECT_TRUE(batch_processor->Shutdown(std::chrono::milliseconds(5000))); + // It's safe to shutdown again + EXPECT_TRUE(batch_processor->Shutdown()); + + EXPECT_EQ(num_spans, spans_received->size()); + for (int i = 0; i < num_spans; ++i) + { + EXPECT_EQ("Span " + std::to_string(i), spans_received->at(i)->GetName()); + } + + EXPECT_TRUE(is_shutdown->load()); +} + +TEST_F(AsyncBatchSpanProcessorTestPeer, TestAsyncShutdownNoCallback) +{ + std::shared_ptr> is_export_completed(new std::atomic(false)); + std::shared_ptr>> spans_received( + new std::vector>); + const std::chrono::milliseconds export_delay(0); + std::shared_ptr> is_shutdown(new std::atomic(false)); + + sdk::trace::AsyncBatchSpanProcessorOptions options{}; + options.max_export_async = 8; + + auto batch_processor = + std::shared_ptr(new sdk::trace::AsyncBatchSpanProcessor( + std::unique_ptr(new MockSpanExporter( + spans_received, is_shutdown, is_export_completed, export_delay, 0)), + options)); + const int num_spans = 2048; + + auto test_spans = GetTestSpans(batch_processor, num_spans); + + for (int i = 0; i < num_spans; ++i) + { + batch_processor->OnEnd(std::move(test_spans->at(i))); + } + + // Shutdown should never block for ever and return on timeout + EXPECT_TRUE(batch_processor->Shutdown(std::chrono::milliseconds(5000))); + // It's safe to shutdown again + EXPECT_TRUE(batch_processor->Shutdown()); + + EXPECT_TRUE(is_shutdown->load()); +} + +TEST_F(AsyncBatchSpanProcessorTestPeer, TestAsyncForceFlush) +{ + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr>> spans_received( + new std::vector>); + + sdk::trace::AsyncBatchSpanProcessorOptions options{}; + + auto batch_processor = + std::shared_ptr(new sdk::trace::AsyncBatchSpanProcessor( + std::unique_ptr(new MockSpanExporter(spans_received, is_shutdown)), + options)); + const int num_spans = 2048; + + auto test_spans = GetTestSpans(batch_processor, num_spans); + + for (int i = 0; i < num_spans; ++i) + { + batch_processor->OnEnd(std::move(test_spans->at(i))); + } + + // Give some time to export + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + + EXPECT_TRUE(batch_processor->ForceFlush()); + + EXPECT_EQ(num_spans, spans_received->size()); + for (int i = 0; i < num_spans; ++i) + { + EXPECT_EQ("Span " + std::to_string(i), spans_received->at(i)->GetName()); + } + + // Create some more spans to make sure that the processor still works + auto more_test_spans = GetTestSpans(batch_processor, num_spans); + for (int i = 0; i < num_spans; ++i) + { + batch_processor->OnEnd(std::move(more_test_spans->at(i))); + } + + // Give some time to export the spans + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + + EXPECT_TRUE(batch_processor->ForceFlush()); + + EXPECT_EQ(num_spans * 2, spans_received->size()); + for (int i = 0; i < num_spans; ++i) + { + EXPECT_EQ("Span " + std::to_string(i % num_spans), + spans_received->at(num_spans + i)->GetName()); + } +} + +TEST_F(AsyncBatchSpanProcessorTestPeer, TestManySpansLoss) +{ + /* Test that when exporting more than max_queue_size spans, some are most likely lost*/ + + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr>> spans_received( + new std::vector>); + + const int max_queue_size = 4096; + + auto batch_processor = + std::shared_ptr(new sdk::trace::AsyncBatchSpanProcessor( + std::unique_ptr(new MockSpanExporter(spans_received, is_shutdown)), + sdk::trace::AsyncBatchSpanProcessorOptions())); + + auto test_spans = GetTestSpans(batch_processor, max_queue_size); + + for (int i = 0; i < max_queue_size; ++i) + { + batch_processor->OnEnd(std::move(test_spans->at(i))); + } + + // Give some time to export the spans + std::this_thread::sleep_for(std::chrono::milliseconds(700)); + + EXPECT_TRUE(batch_processor->ForceFlush()); + + // Span should be exported by now + EXPECT_GE(max_queue_size, spans_received->size()); +} + +TEST_F(AsyncBatchSpanProcessorTestPeer, TestManySpansLossLess) +{ + /* Test that no spans are lost when sending max_queue_size spans */ + + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr>> spans_received( + new std::vector>); + + const int num_spans = 2048; + + auto batch_processor = + std::shared_ptr(new sdk::trace::AsyncBatchSpanProcessor( + std::unique_ptr(new MockSpanExporter(spans_received, is_shutdown)), + sdk::trace::AsyncBatchSpanProcessorOptions())); + + auto test_spans = GetTestSpans(batch_processor, num_spans); + + for (int i = 0; i < num_spans; ++i) + { + batch_processor->OnEnd(std::move(test_spans->at(i))); + } + + // Give some time to export the spans + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + + EXPECT_TRUE(batch_processor->ForceFlush()); + + EXPECT_EQ(num_spans, spans_received->size()); + for (int i = 0; i < num_spans; ++i) + { + EXPECT_EQ("Span " + std::to_string(i), spans_received->at(i)->GetName()); + } +} + +TEST_F(AsyncBatchSpanProcessorTestPeer, TestScheduleDelayMillis) +{ + /* Test that max_export_batch_size spans are exported every schedule_delay_millis + seconds */ + + std::shared_ptr> is_shutdown(new std::atomic(false)); + std::shared_ptr> is_export_completed(new std::atomic(false)); + std::shared_ptr>> spans_received( + new std::vector>); + const std::chrono::milliseconds export_delay(0); + const size_t max_export_batch_size = 512; + sdk::trace::AsyncBatchSpanProcessorOptions options{}; + options.schedule_delay_millis = std::chrono::milliseconds(2000); + + auto batch_processor = + std::shared_ptr(new sdk::trace::AsyncBatchSpanProcessor( + std::unique_ptr( + new MockSpanExporter(spans_received, is_shutdown, is_export_completed, export_delay)), + options)); + + auto test_spans = GetTestSpans(batch_processor, max_export_batch_size); + + for (size_t i = 0; i < max_export_batch_size; ++i) + { + batch_processor->OnEnd(std::move(test_spans->at(i))); + } + + // Sleep for schedule_delay_millis milliseconds + std::this_thread::sleep_for(options.schedule_delay_millis); + + // small delay to give time to export + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + + // Spans should be exported by now + EXPECT_TRUE(is_export_completed->load()); + EXPECT_EQ(max_export_batch_size, spans_received->size()); + for (size_t i = 0; i < max_export_batch_size; ++i) + { + EXPECT_EQ("Span " + std::to_string(i), spans_received->at(i)->GetName()); + } +} + +OPENTELEMETRY_END_NAMESPACE + +#endif diff --git a/sdk/test/trace/batch_span_processor_test.cc b/sdk/test/trace/batch_span_processor_test.cc index e250fd2e55..6f270b9766 100644 --- a/sdk/test/trace/batch_span_processor_test.cc +++ b/sdk/test/trace/batch_span_processor_test.cc @@ -24,20 +24,11 @@ class MockSpanExporter final : public sdk::trace::SpanExporter std::shared_ptr> is_shutdown, std::shared_ptr> is_export_completed = std::shared_ptr>(new std::atomic(false)), - const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0) -#ifdef ENABLE_ASYNC_EXPORT - , - int callback_count = 1 -#endif - ) noexcept + const std::chrono::milliseconds export_delay = std::chrono::milliseconds(0)) noexcept : spans_received_(spans_received), is_shutdown_(is_shutdown), is_export_completed_(is_export_completed), export_delay_(export_delay) -#ifdef ENABLE_ASYNC_EXPORT - , - callback_count_(callback_count) -#endif {} std::unique_ptr MakeRecordable() noexcept override @@ -72,35 +63,15 @@ class MockSpanExporter final : public sdk::trace::SpanExporter std::function &&result_callback) noexcept override { - // We should keep the order of test records + // This is just dummy implementation. auto result = Export(records); - async_threads_.emplace_back(std::make_shared( - [this, - result](std::function &&result_callback) { - for (int i = 0; i < callback_count_; i++) - { - result_callback(result); - } - }, - std::move(result_callback))); + result_callback(result); } #endif bool Shutdown( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override { - while (!async_threads_.empty()) - { - std::list> async_threads; - async_threads.swap(async_threads_); - for (auto &async_thread : async_threads) - { - if (async_thread && async_thread->joinable()) - { - async_thread->join(); - } - } - } *is_shutdown_ = true; return true; } @@ -113,10 +84,6 @@ class MockSpanExporter final : public sdk::trace::SpanExporter std::shared_ptr> is_export_completed_; // Meant exclusively to test force flush timeout const std::chrono::milliseconds export_delay_; - std::list> async_threads_; -#ifdef ENABLE_ASYNC_EXPORT - int callback_count_; -#endif }; /** @@ -177,131 +144,6 @@ TEST_F(BatchSpanProcessorTestPeer, TestShutdown) EXPECT_TRUE(is_shutdown->load()); } -#ifdef ENABLE_ASYNC_EXPORT -TEST_F(BatchSpanProcessorTestPeer, TestAsyncShutdown) -{ - std::shared_ptr>> spans_received( - new std::vector>); - std::shared_ptr> is_shutdown(new std::atomic(false)); - - sdk::trace::BatchSpanProcessorOptions options{}; - options.is_export_async = true; - options.max_export_async = 5; - - auto batch_processor = - std::shared_ptr(new sdk::trace::BatchSpanProcessor( - std::unique_ptr(new MockSpanExporter(spans_received, is_shutdown)), - options)); - const int num_spans = 2048; - - auto test_spans = GetTestSpans(batch_processor, num_spans); - - for (int i = 0; i < num_spans; ++i) - { - batch_processor->OnEnd(std::move(test_spans->at(i))); - } - - EXPECT_TRUE(batch_processor->Shutdown(std::chrono::milliseconds(5000))); - // It's safe to shutdown again - EXPECT_TRUE(batch_processor->Shutdown()); - - EXPECT_EQ(num_spans, spans_received->size()); - for (int i = 0; i < num_spans; ++i) - { - EXPECT_EQ("Span " + std::to_string(i), spans_received->at(i)->GetName()); - } - - EXPECT_TRUE(is_shutdown->load()); -} - -TEST_F(BatchSpanProcessorTestPeer, TestAsyncShutdownNoCallback) -{ - std::shared_ptr> is_export_completed(new std::atomic(false)); - std::shared_ptr>> spans_received( - new std::vector>); - const std::chrono::milliseconds export_delay(0); - std::shared_ptr> is_shutdown(new std::atomic(false)); - - sdk::trace::BatchSpanProcessorOptions options{}; - options.is_export_async = true; - options.max_export_async = 8; - - auto batch_processor = - std::shared_ptr(new sdk::trace::BatchSpanProcessor( - std::unique_ptr(new MockSpanExporter( - spans_received, is_shutdown, is_export_completed, export_delay, 0)), - options)); - const int num_spans = 2048; - - auto test_spans = GetTestSpans(batch_processor, num_spans); - - for (int i = 0; i < num_spans; ++i) - { - batch_processor->OnEnd(std::move(test_spans->at(i))); - } - - // Shutdown should never block for ever and return on timeout - EXPECT_TRUE(batch_processor->Shutdown(std::chrono::milliseconds(5000))); - // It's safe to shutdown again - EXPECT_TRUE(batch_processor->Shutdown()); - - EXPECT_TRUE(is_shutdown->load()); -} - -TEST_F(BatchSpanProcessorTestPeer, TestAsyncForceFlush) -{ - std::shared_ptr> is_shutdown(new std::atomic(false)); - std::shared_ptr>> spans_received( - new std::vector>); - - sdk::trace::BatchSpanProcessorOptions options{}; - options.is_export_async = true; - - auto batch_processor = - std::shared_ptr(new sdk::trace::BatchSpanProcessor( - std::unique_ptr(new MockSpanExporter(spans_received, is_shutdown)), - options)); - const int num_spans = 2048; - - auto test_spans = GetTestSpans(batch_processor, num_spans); - - for (int i = 0; i < num_spans; ++i) - { - batch_processor->OnEnd(std::move(test_spans->at(i))); - } - - // Give some time to export - std::this_thread::sleep_for(std::chrono::milliseconds(50)); - - EXPECT_TRUE(batch_processor->ForceFlush()); - - EXPECT_EQ(num_spans, spans_received->size()); - for (int i = 0; i < num_spans; ++i) - { - EXPECT_EQ("Span " + std::to_string(i), spans_received->at(i)->GetName()); - } - - // Create some more spans to make sure that the processor still works - auto more_test_spans = GetTestSpans(batch_processor, num_spans); - for (int i = 0; i < num_spans; ++i) - { - batch_processor->OnEnd(std::move(more_test_spans->at(i))); - } - - // Give some time to export the spans - std::this_thread::sleep_for(std::chrono::milliseconds(50)); - - EXPECT_TRUE(batch_processor->ForceFlush()); - - EXPECT_EQ(num_spans * 2, spans_received->size()); - for (int i = 0; i < num_spans; ++i) - { - EXPECT_EQ("Span " + std::to_string(i % num_spans), - spans_received->at(num_spans + i)->GetName()); - } -} -#endif - TEST_F(BatchSpanProcessorTestPeer, TestForceFlush) { std::shared_ptr> is_shutdown(new std::atomic(false)); From 1421910c168f3626f5d200f92886238e9a39f7ca Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Thu, 14 Apr 2022 12:41:17 +0530 Subject: [PATCH 06/10] Added changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0eac7fa35a..cdd4622989 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,7 @@ Increment the: * [SDK] Bugfix: span SetAttribute crash ([#1283](https://github.com/open-telemetry/opentelemetry-cpp/pull/1283)) * [EXPORTER] Jaeger Exporter - Populate Span Links ([#1251](https://github.com/open-telemetry/opentelemetry-cpp/pull/1251)) * [EXPORTER] OTLP http exporter allow concurrency session ([#1209](https://github.com/open-telemetry/opentelemetry-cpp/pull/1209)) +* [SDK] Async Batch Span/Log processor with max async support ([#1306](https://github.com/open-telemetry/opentelemetry-cpp/pull/1306)) ## [1.2.0] 2022-01-31 From 4f2fc3bf3878afb54a227cf9ab3c37093f2deca3 Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Tue, 19 Apr 2022 16:24:54 +0530 Subject: [PATCH 07/10] Incorporated Review Comments and added async processor as derived of sync processor --- .../otlp/test/otlp_http_exporter_test.cc | 16 +- .../otlp/test/otlp_http_log_exporter_test.cc | 256 +++++++++++++++--- .../sdk/logs/async_batch_log_processor.h | 112 +------- .../sdk/logs/batch_log_processor.h | 12 +- .../sdk/trace/async_batch_span_processor.h | 107 +------- .../sdk/trace/batch_span_processor.h | 18 +- sdk/src/logs/async_batch_log_processor.cc | 251 +---------------- sdk/src/trace/async_batch_span_processor.cc | 226 +--------------- .../logs/async_batch_log_processor_test.cc | 12 +- .../trace/async_batch_span_processor_test.cc | 4 +- 10 files changed, 292 insertions(+), 722 deletions(-) diff --git a/exporters/otlp/test/otlp_http_exporter_test.cc b/exporters/otlp/test/otlp_http_exporter_test.cc index c25c0111b2..4e4f8f706c 100644 --- a/exporters/otlp/test/otlp_http_exporter_test.cc +++ b/exporters/otlp/test/otlp_http_exporter_test.cc @@ -196,10 +196,10 @@ class OtlpHttpExporterTestPeer : public ::testing::Test resource_attributes["vec_string_value"] = std::vector{"vector", "string"}; auto resource = resource::Resource::Create(resource_attributes); - auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); - processor_opts.max_export_batch_size = 5; - processor_opts.max_queue_size = 5; - processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); + auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); + processor_opts.options.max_export_batch_size = 5; + processor_opts.options.max_queue_size = 5; + processor_opts.options.schedule_delay_millis = std::chrono::milliseconds(256); auto processor = std::unique_ptr( new sdk::trace::AsyncBatchSpanProcessor(std::move(exporter), processor_opts)); @@ -366,10 +366,10 @@ class OtlpHttpExporterTestPeer : public ::testing::Test resource_attributes["vec_string_value"] = std::vector{"vector", "string"}; auto resource = resource::Resource::Create(resource_attributes); - auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); - processor_opts.max_export_batch_size = 5; - processor_opts.max_queue_size = 5; - processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); + auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); + processor_opts.options.max_export_batch_size = 5; + processor_opts.options.max_queue_size = 5; + processor_opts.options.schedule_delay_millis = std::chrono::milliseconds(256); auto processor = std::unique_ptr( new sdk::trace::AsyncBatchSpanProcessor(std::move(exporter), processor_opts)); diff --git a/exporters/otlp/test/otlp_http_log_exporter_test.cc b/exporters/otlp/test/otlp_http_log_exporter_test.cc index a2d125d903..340a3c746c 100644 --- a/exporters/otlp/test/otlp_http_log_exporter_test.cc +++ b/exporters/otlp/test/otlp_http_log_exporter_test.cc @@ -87,7 +87,7 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test return {new OtlpHttpClient(MakeOtlpHttpClientOptions(content_type), http_client), http_client}; } - void ExportJsonIntegrationTest(bool is_async) + void ExportJsonIntegrationTest() { auto mock_otlp_client = OtlpHttpLogExporterTestPeer::GetMockOtlpHttpClient(HttpRequestContentType::kJson); @@ -104,15 +104,10 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test std::string attribute_storage_string_value[] = {"vector", "string"}; auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); -# ifdef ENABLE_ASYNC_EXPORT - provider->AddProcessor( - std::unique_ptr(new sdk::logs::AsyncBatchLogProcessor( - std::move(exporter), 5, std::chrono::milliseconds(256), 5))); -# else + provider->AddProcessor( std::unique_ptr(new sdk::logs::BatchLogProcessor( std::move(exporter), 5, std::chrono::milliseconds(256), 5))); -# endif std::string report_trace_id; std::string report_span_id; @@ -138,7 +133,7 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test auto mock_session = std::static_pointer_cast(no_send_client->session_); EXPECT_CALL(*mock_session, SendRequest) - .WillOnce([&mock_session, report_trace_id, report_span_id, is_async]( + .WillOnce([&mock_session, report_trace_id, report_span_id]( std::shared_ptr callback) { auto check_json = nlohmann::json::parse(mock_session->GetRequest()->body_, nullptr, false); @@ -160,21 +155,112 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test EXPECT_EQ("Custom-Header-Value", custom_header->second); } - // let the otlp_http_client to continue - if (is_async) + http_client::nosend::Response response; + response.Finish(*callback.get()); + }); + + logger->Log(opentelemetry::logs::Severity::kInfo, "Log name", "Log message", + {{"service.name", "unit_test_service"}, + {"tenant.id", "test_user"}, + {"bool_value", true}, + {"int32_value", static_cast(1)}, + {"uint32_value", static_cast(2)}, + {"int64_value", static_cast(0x1100000000LL)}, + {"uint64_value", static_cast(0x1200000000ULL)}, + {"double_value", static_cast(3.1)}, + {"vec_bool_value", attribute_storage_bool_value}, + {"vec_int32_value", attribute_storage_int32_value}, + {"vec_uint32_value", attribute_storage_uint32_value}, + {"vec_int64_value", attribute_storage_int64_value}, + {"vec_uint64_value", attribute_storage_uint64_value}, + {"vec_double_value", attribute_storage_double_value}, + {"vec_string_value", attribute_storage_string_value}}, + trace_id, span_id, + opentelemetry::trace::TraceFlags{opentelemetry::trace::TraceFlags::kIsSampled}, + std::chrono::system_clock::now()); + + provider->ForceFlush(); + } + +# ifdef ENABLE_ASYNC_EXPORT + void ExportJsonIntegrationTestAsync() + { + auto mock_otlp_client = + OtlpHttpLogExporterTestPeer::GetMockOtlpHttpClient(HttpRequestContentType::kJson); + auto mock_otlp_http_client = mock_otlp_client.first; + auto client = mock_otlp_client.second; + auto exporter = GetExporter(std::unique_ptr{mock_otlp_http_client}); + + bool attribute_storage_bool_value[] = {true, false, true}; + int32_t attribute_storage_int32_value[] = {1, 2}; + uint32_t attribute_storage_uint32_value[] = {3, 4}; + int64_t attribute_storage_int64_value[] = {5, 6}; + uint64_t attribute_storage_uint64_value[] = {7, 8}; + double attribute_storage_double_value[] = {3.2, 3.3}; + std::string attribute_storage_string_value[] = {"vector", "string"}; + + auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); + sdk::logs::AsyncBatchLogProcessorOptions options; + options.options.max_queue_size = 5; + options.options.schedule_delay_millis = std::chrono::milliseconds(256); + options.options.max_export_batch_size = 5; + + provider->AddProcessor(std::unique_ptr( + new sdk::logs::AsyncBatchLogProcessor(std::move(exporter), options))); + + std::string report_trace_id; + std::string report_span_id; + uint8_t trace_id_bin[opentelemetry::trace::TraceId::kSize] = { + '0', '1', '2', '3', '4', '5', '6', '7', '8', '9', 'a', 'b', 'c', 'd', 'e', 'f'}; + char trace_id_hex[2 * opentelemetry::trace::TraceId::kSize] = {0}; + opentelemetry::trace::TraceId trace_id{trace_id_bin}; + uint8_t span_id_bin[opentelemetry::trace::SpanId::kSize] = {'7', '6', '5', '4', + '3', '2', '1', '0'}; + char span_id_hex[2 * opentelemetry::trace::SpanId::kSize] = {0}; + opentelemetry::trace::SpanId span_id{span_id_bin}; + + const std::string schema_url{"https://opentelemetry.io/schemas/1.2.0"}; + auto logger = provider->GetLogger("test", "", "opentelelemtry_library", "", schema_url); + + trace_id.ToLowerBase16(MakeSpan(trace_id_hex)); + report_trace_id.assign(trace_id_hex, sizeof(trace_id_hex)); + + span_id.ToLowerBase16(MakeSpan(span_id_hex)); + report_span_id.assign(span_id_hex, sizeof(span_id_hex)); + + auto no_send_client = std::static_pointer_cast(client); + auto mock_session = + std::static_pointer_cast(no_send_client->session_); + EXPECT_CALL(*mock_session, SendRequest) + .WillOnce([&mock_session, report_trace_id, report_span_id]( + std::shared_ptr callback) { + auto check_json = + nlohmann::json::parse(mock_session->GetRequest()->body_, nullptr, false); + auto resource_logs = *check_json["resource_logs"].begin(); + auto instrumentation_library_span = + *resource_logs["instrumentation_library_logs"].begin(); + auto log = *instrumentation_library_span["logs"].begin(); + auto received_trace_id = log["trace_id"].get(); + auto received_span_id = log["span_id"].get(); + EXPECT_EQ(received_trace_id, report_trace_id); + EXPECT_EQ(received_span_id, report_span_id); + EXPECT_EQ("Log name", log["name"].get()); + EXPECT_EQ("Log message", log["body"]["string_value"].get()); + EXPECT_LE(15, log["attributes"].size()); + auto custom_header = mock_session->GetRequest()->headers_.find("Custom-Header-Key"); + ASSERT_TRUE(custom_header != mock_session->GetRequest()->headers_.end()); + if (custom_header != mock_session->GetRequest()->headers_.end()) { - std::thread async_finish{[callback]() { - std::this_thread::sleep_for(std::chrono::milliseconds(100)); - http_client::nosend::Response response; - response.Finish(*callback.get()); - }}; - async_finish.detach(); + EXPECT_EQ("Custom-Header-Value", custom_header->second); } - else - { + + // let the otlp_http_client to continue + std::thread async_finish{[callback]() { + std::this_thread::sleep_for(std::chrono::milliseconds(100)); http_client::nosend::Response response; response.Finish(*callback.get()); - } + }}; + async_finish.detach(); }); logger->Log(opentelemetry::logs::Severity::kInfo, "Log name", "Log message", @@ -199,8 +285,9 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test provider->ForceFlush(); } +# endif - void ExportBinaryIntegrationTest(bool is_async) + void ExportBinaryIntegrationTest() { auto mock_otlp_client = OtlpHttpLogExporterTestPeer::GetMockOtlpHttpClient(HttpRequestContentType::kBinary); @@ -217,21 +304,12 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test std::string attribute_storage_string_value[] = {"vector", "string"}; auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); -# ifdef ENABLE_ASYNC_EXPORT - sdk::logs::AsyncBatchLogProcessorOptions processor_options; - processor_options.max_export_batch_size = 5; - processor_options.max_queue_size = 5; - processor_options.schedule_delay_millis = std::chrono::milliseconds(256); - provider->AddProcessor(std::unique_ptr( - new sdk::logs::AsyncBatchLogProcessor(std::move(exporter), processor_options))); -# else sdk::logs::BatchLogProcessorOptions processor_options; processor_options.max_export_batch_size = 5; processor_options.max_queue_size = 5; processor_options.schedule_delay_millis = std::chrono::milliseconds(256); provider->AddProcessor(std::unique_ptr( new sdk::logs::BatchLogProcessor(std::move(exporter), processor_options))); -# endif std::string report_trace_id; std::string report_span_id; @@ -252,7 +330,7 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test auto mock_session = std::static_pointer_cast(no_send_client->session_); EXPECT_CALL(*mock_session, SendRequest) - .WillOnce([&mock_session, report_trace_id, report_span_id, is_async]( + .WillOnce([&mock_session, report_trace_id, report_span_id]( std::shared_ptr callback) { opentelemetry::proto::collector::logs::v1::ExportLogsServiceRequest request_body; request_body.ParseFromArray(&mock_session->GetRequest()->body_[0], @@ -275,20 +353,109 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test ASSERT_TRUE(check_service_name); // let the otlp_http_client to continue - if (is_async) + + http_client::nosend::Response response; + response.Finish(*callback.get()); + }); + + logger->Log(opentelemetry::logs::Severity::kInfo, "Log name", "Log message", + {{"service.name", "unit_test_service"}, + {"tenant.id", "test_user"}, + {"bool_value", true}, + {"int32_value", static_cast(1)}, + {"uint32_value", static_cast(2)}, + {"int64_value", static_cast(0x1100000000LL)}, + {"uint64_value", static_cast(0x1200000000ULL)}, + {"double_value", static_cast(3.1)}, + {"vec_bool_value", attribute_storage_bool_value}, + {"vec_int32_value", attribute_storage_int32_value}, + {"vec_uint32_value", attribute_storage_uint32_value}, + {"vec_int64_value", attribute_storage_int64_value}, + {"vec_uint64_value", attribute_storage_uint64_value}, + {"vec_double_value", attribute_storage_double_value}, + {"vec_string_value", attribute_storage_string_value}}, + trace_id, span_id, + opentelemetry::trace::TraceFlags{opentelemetry::trace::TraceFlags::kIsSampled}, + std::chrono::system_clock::now()); + + provider->ForceFlush(); + } + +# ifdef ENABLE_ASYNC_EXPORT + void ExportBinaryIntegrationTestAsync() + { + auto mock_otlp_client = + OtlpHttpLogExporterTestPeer::GetMockOtlpHttpClient(HttpRequestContentType::kBinary); + auto mock_otlp_http_client = mock_otlp_client.first; + auto client = mock_otlp_client.second; + auto exporter = GetExporter(std::unique_ptr{mock_otlp_http_client}); + + bool attribute_storage_bool_value[] = {true, false, true}; + int32_t attribute_storage_int32_value[] = {1, 2}; + uint32_t attribute_storage_uint32_value[] = {3, 4}; + int64_t attribute_storage_int64_value[] = {5, 6}; + uint64_t attribute_storage_uint64_value[] = {7, 8}; + double attribute_storage_double_value[] = {3.2, 3.3}; + std::string attribute_storage_string_value[] = {"vector", "string"}; + + auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); + + sdk::logs::AsyncBatchLogProcessorOptions processor_options; + processor_options.options.max_export_batch_size = 5; + processor_options.options.max_queue_size = 5; + processor_options.options.schedule_delay_millis = std::chrono::milliseconds(256); + provider->AddProcessor(std::unique_ptr( + new sdk::logs::AsyncBatchLogProcessor(std::move(exporter), processor_options))); + + std::string report_trace_id; + std::string report_span_id; + uint8_t trace_id_bin[opentelemetry::trace::TraceId::kSize] = { + '0', '1', '2', '3', '4', '5', '6', '7', '8', '9', 'a', 'b', 'c', 'd', 'e', 'f'}; + opentelemetry::trace::TraceId trace_id{trace_id_bin}; + uint8_t span_id_bin[opentelemetry::trace::SpanId::kSize] = {'7', '6', '5', '4', + '3', '2', '1', '0'}; + opentelemetry::trace::SpanId span_id{span_id_bin}; + + const std::string schema_url{"https://opentelemetry.io/schemas/1.2.0"}; + auto logger = provider->GetLogger("test", "", "opentelelemtry_library", "", schema_url); + + report_trace_id.assign(reinterpret_cast(trace_id_bin), sizeof(trace_id_bin)); + report_span_id.assign(reinterpret_cast(span_id_bin), sizeof(span_id_bin)); + + auto no_send_client = std::static_pointer_cast(client); + auto mock_session = + std::static_pointer_cast(no_send_client->session_); + EXPECT_CALL(*mock_session, SendRequest) + .WillOnce([&mock_session, report_trace_id, report_span_id]( + std::shared_ptr callback) { + opentelemetry::proto::collector::logs::v1::ExportLogsServiceRequest request_body; + request_body.ParseFromArray(&mock_session->GetRequest()->body_[0], + static_cast(mock_session->GetRequest()->body_.size())); + auto received_log = request_body.resource_logs(0).instrumentation_library_logs(0).logs(0); + EXPECT_EQ(received_log.trace_id(), report_trace_id); + EXPECT_EQ(received_log.span_id(), report_span_id); + EXPECT_EQ("Log name", received_log.name()); + EXPECT_EQ("Log message", received_log.body().string_value()); + EXPECT_LE(15, received_log.attributes_size()); + bool check_service_name = false; + for (auto &attribute : received_log.attributes()) { - std::thread async_finish{[callback]() { - std::this_thread::sleep_for(std::chrono::milliseconds(100)); - http_client::nosend::Response response; - response.Finish(*callback.get()); - }}; - async_finish.detach(); + if ("service.name" == attribute.key()) + { + check_service_name = true; + EXPECT_EQ("unit_test_service", attribute.value().string_value()); + } } - else - { + ASSERT_TRUE(check_service_name); + + // let the otlp_http_client to continue + + std::thread async_finish{[callback]() { + std::this_thread::sleep_for(std::chrono::milliseconds(100)); http_client::nosend::Response response; response.Finish(*callback.get()); - } + }}; + async_finish.detach(); }); logger->Log(opentelemetry::logs::Severity::kInfo, "Log name", "Log message", @@ -313,31 +480,32 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test provider->ForceFlush(); } +# endif }; // Create log records, let processor call Export() TEST_F(OtlpHttpLogExporterTestPeer, ExportJsonIntegrationTestSync) { - ExportJsonIntegrationTest(false); + ExportJsonIntegrationTest(); } # ifdef ENABLE_ASYNC_EXPORT TEST_F(OtlpHttpLogExporterTestPeer, ExportJsonIntegrationTestAsync) { - ExportJsonIntegrationTest(true); + ExportJsonIntegrationTestAsync(); } # endif // Create log records, let processor call Export() TEST_F(OtlpHttpLogExporterTestPeer, ExportBinaryIntegrationTestSync) { - ExportBinaryIntegrationTest(false); + ExportBinaryIntegrationTest(); } # ifdef ENABLE_ASYNC_EXPORT TEST_F(OtlpHttpLogExporterTestPeer, ExportBinaryIntegrationTestAsync) { - ExportBinaryIntegrationTest(true); + ExportBinaryIntegrationTestAsync(); } # endif diff --git a/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h index 8c097af4f6..a307c68a69 100644 --- a/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h @@ -6,17 +6,15 @@ # ifdef ENABLE_ASYNC_EXPORT # include "opentelemetry/sdk/common/circular_buffer.h" +# include "opentelemetry/sdk/logs/batch_log_processor.h" # include "opentelemetry/sdk/logs/exporter.h" -# include "opentelemetry/sdk/logs/processor.h" # include # include # include # include +# include # include -# ifdef ENABLE_ASYNC_EXPORT -# include -# endif OPENTELEMETRY_BEGIN_NAMESPACE namespace sdk @@ -30,20 +28,7 @@ namespace logs */ struct AsyncBatchLogProcessorOptions { - /** - * The maximum buffer/queue size. After the size is reached, spans are - * dropped. - */ - size_t max_queue_size = 2048; - - /* The time interval between two consecutive exports. */ - std::chrono::milliseconds schedule_delay_millis = std::chrono::milliseconds(5000); - - /** - * The maximum batch size of every export. It must be smaller or - * equal to max_queue_size. - */ - size_t max_export_batch_size = 512; + BatchLogProcessorOptions options; /* Denotes the maximum number of async exports to continue */ @@ -54,27 +39,9 @@ struct AsyncBatchLogProcessorOptions * This is an implementation of the LogProcessor which creates batches of finished logs and passes * the export-friendly log data representations to the configured LogExporter. */ -class AsyncBatchLogProcessor : public LogProcessor +class AsyncBatchLogProcessor : public BatchLogProcessor { public: - /** - * Creates a batch log processor by configuring the specified exporter and other parameters - * as per the official, language-agnostic opentelemetry specs. - * - * @param exporter - The backend exporter to pass the logs to - * @param max_queue_size - The maximum buffer/queue size. After the size is reached, logs are - * dropped. - * @param scheduled_delay_millis - The time interval between two consecutive exports. - * @param max_export_batch_size - The maximum batch size of every export. It must be smaller or - * equal to max_queue_size - */ - explicit AsyncBatchLogProcessor( - std::unique_ptr &&exporter, - const size_t max_queue_size = 2048, - const std::chrono::milliseconds scheduled_delay_millis = std::chrono::milliseconds(5000), - const size_t max_export_batch_size = 512, - const size_t max_export_async = 8); - /** * Creates a batch log processor by configuring the specified exporter and other parameters * as per the official, language-agnostic opentelemetry specs. @@ -85,24 +52,6 @@ class AsyncBatchLogProcessor : public LogProcessor explicit AsyncBatchLogProcessor(std::unique_ptr &&exporter, const AsyncBatchLogProcessorOptions &options); - /** Makes a new recordable **/ - std::unique_ptr MakeRecordable() noexcept override; - - /** - * Called when the Logger's log method creates a log record - * @param record the log record - */ - - void OnReceive(std::unique_ptr &&record) noexcept override; - - /** - * Export all log records that have not been exported yet. - * - * NOTE: Timeout functionality not supported yet. - */ - bool ForceFlush( - std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; - /** * Shuts down the processor and does any cleanup required. Completely drains the buffer/queue of * all its logs and passes them to the exporter. Any subsequent calls to @@ -119,49 +68,25 @@ class AsyncBatchLogProcessor : public LogProcessor virtual ~AsyncBatchLogProcessor() override; private: - /** - * The background routine performed by the worker thread. - */ - void DoBackgroundWork(); - /** * Exports all logs to the configured exporter. * */ - void Export(); - - /** - * Called when Shutdown() is invoked. Completely drains the queue of all log records and - * passes them to the exporter. - */ - void DrainQueue(); + void Export() override; struct ExportDataStorage { std::queue export_ids; std::vector export_ids_flag; + + std::condition_variable async_export_waker; + std::mutex async_export_data_m; }; std::shared_ptr export_data_storage_; const size_t max_export_async_; static constexpr size_t kInvalidExportId = static_cast(-1); - struct SynchronizationData - { - /* Synchronization primitives */ - std::condition_variable cv, force_flush_cv; - std::mutex cv_m, force_flush_cv_m, shutdown_m; - - /* Important boolean flags to handle the workflow of the processor */ - std::atomic is_force_wakeup_background_worker; - std::atomic is_force_flush_pending; - std::atomic is_force_flush_notified; - std::atomic is_shutdown; - - std::condition_variable async_export_waker; - std::mutex async_export_data_m; - }; - /** * @brief Notify completion of shutdown and force flush. This may be called from the any thread at * any time @@ -170,25 +95,8 @@ class AsyncBatchLogProcessor : public LogProcessor * @param synchronization_data Synchronization data to be notified. */ static void NotifyCompletion(bool notify_force_flush, - const std::shared_ptr &synchronization_data); - - void GetWaitAdjustedTime(std::chrono::microseconds &timeout, - std::chrono::time_point &start_time); - - /* The configured backend log exporter */ - std::unique_ptr exporter_; - - /* Configurable parameters as per the official *trace* specs */ - const size_t max_queue_size_; - const std::chrono::milliseconds scheduled_delay_millis_; - const size_t max_export_batch_size_; - /* The buffer/queue to which the ended logs are added */ - common::CircularBuffer buffer_; - - std::shared_ptr synchronization_data_; - - /* The background worker thread */ - std::thread worker_thread_; + const std::shared_ptr &synchronization_data, + const std::shared_ptr &export_data_storage); }; } // namespace logs diff --git a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h index 636281704d..1ddc518137 100644 --- a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h @@ -77,21 +77,21 @@ class BatchLogProcessor : public LogProcessor const BatchLogProcessorOptions &options); /** Makes a new recordable **/ - std::unique_ptr MakeRecordable() noexcept override; + virtual std::unique_ptr MakeRecordable() noexcept override; /** * Called when the Logger's log method creates a log record * @param record the log record */ - void OnReceive(std::unique_ptr &&record) noexcept override; + virtual void OnReceive(std::unique_ptr &&record) noexcept override; /** * Export all log records that have not been exported yet. * * NOTE: Timeout functionality not supported yet. */ - bool ForceFlush( + virtual bool ForceFlush( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; /** @@ -101,7 +101,7 @@ class BatchLogProcessor : public LogProcessor * * NOTE: Timeout functionality not supported yet. */ - bool Shutdown( + virtual bool Shutdown( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; /** @@ -109,7 +109,7 @@ class BatchLogProcessor : public LogProcessor */ virtual ~BatchLogProcessor() override; -private: +protected: /** * The background routine performed by the worker thread. */ @@ -119,7 +119,7 @@ class BatchLogProcessor : public LogProcessor * Exports all logs to the configured exporter. * */ - void Export(); + virtual void Export(); /** * Called when Shutdown() is invoked. Completely drains the queue of all log records and diff --git a/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h index 6798a3f507..03801f41dc 100644 --- a/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h @@ -5,8 +5,8 @@ #ifdef ENABLE_ASYNC_EXPORT # include "opentelemetry/sdk/common/circular_buffer.h" +# include "opentelemetry/sdk/trace/batch_span_processor.h" # include "opentelemetry/sdk/trace/exporter.h" -# include "opentelemetry/sdk/trace/processor.h" # include # include @@ -25,20 +25,7 @@ namespace trace */ struct AsyncBatchSpanProcessorOptions { - /** - * The maximum buffer/queue size. After the size is reached, spans are - * dropped. - */ - size_t max_queue_size = 2048; - - /* The time interval between two consecutive exports. */ - std::chrono::milliseconds schedule_delay_millis = std::chrono::milliseconds(5000); - - /** - * The maximum batch size of every export. It must be smaller or - * equal to max_queue_size. - */ - size_t max_export_batch_size = 512; + BatchSpanProcessorOptions options; /* Denotes the maximum number of async exports to continue */ @@ -49,7 +36,7 @@ struct AsyncBatchSpanProcessorOptions * This is an implementation of the SpanProcessor which creates batches of finished spans and passes * the export-friendly span data representations to the configured SpanExporter. */ -class AsyncBatchSpanProcessor : public SpanProcessor +class AsyncBatchSpanProcessor : public BatchSpanProcessor { public: /** @@ -62,39 +49,6 @@ class AsyncBatchSpanProcessor : public SpanProcessor AsyncBatchSpanProcessor(std::unique_ptr &&exporter, const AsyncBatchSpanProcessorOptions &options); - /** - * Requests a Recordable(Span) from the configured exporter. - * - * @return A recordable generated by the backend exporter - */ - std::unique_ptr MakeRecordable() noexcept override; - - /** - * Called when a span is started. - * - * NOTE: This method is a no-op. - * - * @param span - The span that just started - * @param parent_context - The parent context of the span that just started - */ - void OnStart(Recordable &span, - const opentelemetry::trace::SpanContext &parent_context) noexcept override; - - /** - * Called when a span ends. - * - * @param span - A recordable for a span that just ended - */ - void OnEnd(std::unique_ptr &&span) noexcept override; - - /** - * Export all ended spans that have not been exported yet. - * - * NOTE: Timeout functionality not supported yet. - */ - bool ForceFlush( - std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; - /** * Shuts down the processor and does any cleanup required. Completely drains the buffer/queue of * all its ended spans and passes them to the exporter. Any subsequent calls to OnStart, OnEnd, @@ -111,52 +65,28 @@ class AsyncBatchSpanProcessor : public SpanProcessor * shared ownership of the processor, and thus doesn't call Shutdown (as the processor might be * shared with other Tracers). */ - ~AsyncBatchSpanProcessor(); + virtual ~AsyncBatchSpanProcessor() override; private: - /** - * The background routine performed by the worker thread. - */ - void DoBackgroundWork(); - /** * Exports all ended spans to the configured exporter. * */ - void Export(); - - /** - * Called when Shutdown() is invoked. Completely drains the queue of all its ended spans and - * passes them to the exporter. - */ - void DrainQueue(); + void Export() override; struct ExportDataStorage { std::queue export_ids; std::vector export_ids_flag; + + std::condition_variable async_export_waker; + std::mutex async_export_data_m; }; std::shared_ptr export_data_storage_; const size_t max_export_async_; static constexpr size_t kInvalidExportId = static_cast(-1); - struct SynchronizationData - { - /* Synchronization primitives */ - std::condition_variable cv, force_flush_cv; - std::mutex cv_m, force_flush_cv_m, shutdown_m; - - /* Important boolean flags to handle the workflow of the processor */ - std::atomic is_force_wakeup_background_worker; - std::atomic is_force_flush_pending; - std::atomic is_force_flush_notified; - std::atomic is_shutdown; - - std::condition_variable async_export_waker; - std::mutex async_export_data_m; - }; - /** * @brief Notify completion of shutdown and force flush. This may be called from the any thread at * any time @@ -165,25 +95,8 @@ class AsyncBatchSpanProcessor : public SpanProcessor * @param synchronization_data Synchronization data to be notified. */ static void NotifyCompletion(bool notify_force_flush, - const std::shared_ptr &synchronization_data); - - void GetWaitAdjustedTime(std::chrono::microseconds &timeout, - std::chrono::time_point &start_time); - /* The configured backend exporter */ - std::unique_ptr exporter_; - - /* Configurable parameters as per the official specs */ - const size_t max_queue_size_; - const std::chrono::milliseconds schedule_delay_millis_; - const size_t max_export_batch_size_; - - /* The buffer/queue to which the ended spans are added */ - common::CircularBuffer buffer_; - - std::shared_ptr synchronization_data_; - - /* The background worker thread */ - std::thread worker_thread_; + const std::shared_ptr &synchronization_data, + const std::shared_ptr &export_data_storage); }; } // namespace trace diff --git a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h index e404e41878..8f61d0ffc8 100644 --- a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h @@ -61,7 +61,7 @@ class BatchSpanProcessor : public SpanProcessor * * @return A recordable generated by the backend exporter */ - std::unique_ptr MakeRecordable() noexcept override; + virtual std::unique_ptr MakeRecordable() noexcept override; /** * Called when a span is started. @@ -71,22 +71,22 @@ class BatchSpanProcessor : public SpanProcessor * @param span - The span that just started * @param parent_context - The parent context of the span that just started */ - void OnStart(Recordable &span, - const opentelemetry::trace::SpanContext &parent_context) noexcept override; + virtual void OnStart(Recordable &span, + const opentelemetry::trace::SpanContext &parent_context) noexcept override; /** * Called when a span ends. * * @param span - A recordable for a span that just ended */ - void OnEnd(std::unique_ptr &&span) noexcept override; + virtual void OnEnd(std::unique_ptr &&span) noexcept override; /** * Export all ended spans that have not been exported yet. * * NOTE: Timeout functionality not supported yet. */ - bool ForceFlush( + virtual bool ForceFlush( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; /** @@ -96,7 +96,7 @@ class BatchSpanProcessor : public SpanProcessor * * NOTE: Timeout functionality not supported yet. */ - bool Shutdown( + virtual bool Shutdown( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; /** @@ -105,9 +105,9 @@ class BatchSpanProcessor : public SpanProcessor * shared ownership of the processor, and thus doesn't call Shutdown (as the processor might be * shared with other Tracers). */ - ~BatchSpanProcessor(); + virtual ~BatchSpanProcessor(); -private: +protected: /** * The background routine performed by the worker thread. */ @@ -117,7 +117,7 @@ class BatchSpanProcessor : public SpanProcessor * Exports all ended spans to the configured exporter. * */ - void Export(); + virtual void Export(); /** * Called when Shutdown() is invoked. Completely drains the queue of all its ended spans and diff --git a/sdk/src/logs/async_batch_log_processor.cc b/sdk/src/logs/async_batch_log_processor.cc index c23ffbe042..f266ea0b44 100644 --- a/sdk/src/logs/async_batch_log_processor.cc +++ b/sdk/src/logs/async_batch_log_processor.cc @@ -15,51 +15,12 @@ namespace sdk { namespace logs { -AsyncBatchLogProcessor::AsyncBatchLogProcessor( - std::unique_ptr &&exporter, - const size_t max_queue_size, - const std::chrono::milliseconds scheduled_delay_millis, - const size_t max_export_batch_size, - const size_t max_export_async) - : exporter_(std::move(exporter)), - max_queue_size_(max_queue_size), - scheduled_delay_millis_(scheduled_delay_millis), - max_export_batch_size_(max_export_batch_size), - max_export_async_(max_export_async), - export_data_storage_(std::make_shared()), - buffer_(max_queue_size_), - synchronization_data_(std::make_shared()), - worker_thread_(&AsyncBatchLogProcessor::DoBackgroundWork, this) -{ - synchronization_data_->is_force_wakeup_background_worker.store(false); - synchronization_data_->is_force_flush_pending.store(false); - synchronization_data_->is_force_flush_notified.store(false); - synchronization_data_->is_shutdown.store(false); - - export_data_storage_->export_ids_flag.resize(max_export_async_, true); - for (size_t i = 1; i <= max_export_async_; i++) - { - export_data_storage_->export_ids.push(i); - } -} - AsyncBatchLogProcessor::AsyncBatchLogProcessor(std::unique_ptr &&exporter, const AsyncBatchLogProcessorOptions &options) - : exporter_(std::move(exporter)), - max_queue_size_(options.max_queue_size), - scheduled_delay_millis_(options.schedule_delay_millis), - max_export_batch_size_(options.max_export_batch_size), + : BatchLogProcessor(std::move(exporter), options.options), max_export_async_(options.max_export_async), - export_data_storage_(std::make_shared()), - buffer_(options.max_queue_size), - synchronization_data_(std::make_shared()), - worker_thread_(&AsyncBatchLogProcessor::DoBackgroundWork, this) + export_data_storage_(std::make_shared()) { - synchronization_data_->is_force_wakeup_background_worker.store(false); - synchronization_data_->is_force_flush_pending.store(false); - synchronization_data_->is_force_flush_notified.store(false); - synchronization_data_->is_shutdown.store(false); - export_data_storage_->export_ids_flag.resize(max_export_async_, true); for (int i = 1; i <= max_export_async_; i++) { @@ -67,143 +28,8 @@ AsyncBatchLogProcessor::AsyncBatchLogProcessor(std::unique_ptr &&ex } } -std::unique_ptr AsyncBatchLogProcessor::MakeRecordable() noexcept -{ - return exporter_->MakeRecordable(); -} - -void AsyncBatchLogProcessor::OnReceive(std::unique_ptr &&record) noexcept -{ - if (synchronization_data_->is_shutdown.load() == true) - { - return; - } - - if (buffer_.Add(record) == false) - { - return; - } - - // If the queue gets at least half full a preemptive notification is - // sent to the worker thread to start a new export cycle. - size_t buffer_size = buffer_.size(); - if (buffer_size >= max_queue_size_ / 2 || buffer_size >= max_export_batch_size_) - { - // signal the worker thread - synchronization_data_->is_force_wakeup_background_worker.store(true, std::memory_order_release); - synchronization_data_->cv.notify_one(); - } -} - -bool AsyncBatchLogProcessor::ForceFlush(std::chrono::microseconds timeout) noexcept -{ - if (synchronization_data_->is_shutdown.load() == true) - { - return false; - } - - // Now wait for the worker thread to signal back from the Export method - std::unique_lock lk_cv(synchronization_data_->force_flush_cv_m); - - synchronization_data_->is_force_flush_pending.store(true, std::memory_order_release); - auto break_condition = [this]() { - if (synchronization_data_->is_shutdown.load() == true) - { - return true; - } - - // Wake up the worker thread once. - if (synchronization_data_->is_force_flush_pending.load(std::memory_order_acquire)) - { - synchronization_data_->cv.notify_one(); - } - - return synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire); - }; - - // Fix timeout to meet requirement of wait_for - timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( - timeout, std::chrono::microseconds::zero()); - bool result; - if (timeout <= std::chrono::microseconds::zero()) - { - bool wait_result = false; - while (!wait_result) - { - // When is_force_flush_notified.store(true) and force_flush_cv.notify_all() is called - // between is_force_flush_pending.load() and force_flush_cv.wait(). We must not wait - // for ever - wait_result = synchronization_data_->force_flush_cv.wait_for(lk_cv, scheduled_delay_millis_, - break_condition); - } - result = true; - } - else - { - result = synchronization_data_->force_flush_cv.wait_for(lk_cv, timeout, break_condition); - } - - // If it's already signaled, we must wait util notified. - // We use a spin lock here - if (false == - synchronization_data_->is_force_flush_pending.exchange(false, std::memory_order_acq_rel)) - { - for (int retry_waiting_times = 0; - false == synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire); - ++retry_waiting_times) - { - opentelemetry::common::SpinLockMutex::fast_yield(); - if ((retry_waiting_times & 127) == 127) - { - std::this_thread::yield(); - } - } - } - - synchronization_data_->is_force_flush_notified.store(false, std::memory_order_release); - - return result; -} - -void AsyncBatchLogProcessor::DoBackgroundWork() -{ - auto timeout = scheduled_delay_millis_; - - while (true) - { - // Wait for `timeout` milliseconds - std::unique_lock lk(synchronization_data_->cv_m); - synchronization_data_->cv.wait_for(lk, timeout, [this] { - if (synchronization_data_->is_force_wakeup_background_worker.load(std::memory_order_acquire)) - { - return true; - } - - return !buffer_.empty(); - }); - synchronization_data_->is_force_wakeup_background_worker.store(false, - std::memory_order_release); - - if (synchronization_data_->is_shutdown.load() == true) - { - DrainQueue(); - return; - } - - auto start = std::chrono::steady_clock::now(); - Export(); - auto end = std::chrono::steady_clock::now(); - auto duration = std::chrono::duration_cast(end - start); - - // Subtract the duration of this export call from the next `timeout`. - timeout = scheduled_delay_millis_ - duration; - } -} - void AsyncBatchLogProcessor::Export() { - uint64_t current_pending; - uint64_t current_notified; do { std::vector> records_arr; @@ -222,7 +48,7 @@ void AsyncBatchLogProcessor::Export() if (num_records_to_export == 0) { - NotifyCompletion(notify_force_flush, synchronization_data_); + NotifyCompletion(notify_force_flush, synchronization_data_, export_data_storage_); break; } @@ -238,8 +64,8 @@ void AsyncBatchLogProcessor::Export() size_t id = kInvalidExportId; { - std::unique_lock lock(synchronization_data_->async_export_data_m); - synchronization_data_->async_export_waker.wait_for(lock, scheduled_delay_millis_, [this] { + std::unique_lock lock(export_data_storage_->async_export_data_m); + export_data_storage_->async_export_waker.wait_for(lock, scheduled_delay_millis_, [this] { return export_data_storage_->export_ids.size() > 0; }); if (export_data_storage_->export_ids.size() > 0) @@ -270,7 +96,7 @@ void AsyncBatchLogProcessor::Export() auto synchronization_data = synchronization_data_watcher.lock(); auto export_data = export_data_watcher.lock(); { - std::unique_lock lk(synchronization_data->async_export_data_m); + std::unique_lock lk(export_data->async_export_data_m); // In case callback is called more than once due to some bug in exporter // we need to ensure export_ids do not contain duplicate. if (export_data->export_ids_flag[id - 1] == false) @@ -285,7 +111,7 @@ void AsyncBatchLogProcessor::Export() } if (is_already_notified == false) { - NotifyCompletion(notify_force_flush, synchronization_data); + NotifyCompletion(notify_force_flush, synchronization_data, export_data); } return true; }); @@ -295,54 +121,11 @@ void AsyncBatchLogProcessor::Export() void AsyncBatchLogProcessor::NotifyCompletion( bool notify_force_flush, - const std::shared_ptr &synchronization_data) + const std::shared_ptr &synchronization_data, + const std::shared_ptr &export_data_storage) { - if (!synchronization_data) - { - return; - } - - if (notify_force_flush) - { - synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); - synchronization_data->force_flush_cv.notify_one(); - } - - synchronization_data->async_export_waker.notify_all(); -} - -void AsyncBatchLogProcessor::DrainQueue() -{ - while (true) - { - if (buffer_.empty() && - false == synchronization_data_->is_force_flush_pending.load(std::memory_order_acquire)) - { - break; - } - - Export(); - } -} - -void AsyncBatchLogProcessor::GetWaitAdjustedTime( - std::chrono::microseconds &timeout, - std::chrono::time_point &start_time) -{ - auto end_time = std::chrono::system_clock::now(); - auto offset = std::chrono::duration_cast(end_time - start_time); - start_time = end_time; - timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( - timeout, std::chrono::microseconds::zero()); - if (timeout > offset && timeout > std::chrono::microseconds::zero()) - { - timeout -= offset; - } - else - { - // Some module use zero as indefinite timeout.So we can not reset timeout to zero here - timeout = std::chrono::microseconds(1); - } + BatchLogProcessor::NotifyCompletion(notify_force_flush, synchronization_data); + export_data_storage->async_export_waker.notify_all(); } bool AsyncBatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcept @@ -362,8 +145,8 @@ bool AsyncBatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcep GetWaitAdjustedTime(timeout, start_time); // wait for all async exports to complete and return if timeout reached. { - std::unique_lock lock(synchronization_data_->async_export_data_m); - synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { + std::unique_lock lock(export_data_storage_->async_export_data_m); + export_data_storage_->async_export_waker.wait_for(lock, timeout, [this] { return export_data_storage_->export_ids.size() == max_export_async_; }); } @@ -378,13 +161,7 @@ bool AsyncBatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcep return true; } -AsyncBatchLogProcessor::~AsyncBatchLogProcessor() -{ - if (synchronization_data_->is_shutdown.load() == false) - { - Shutdown(); - } -} +AsyncBatchLogProcessor::~AsyncBatchLogProcessor() {} } // namespace logs } // namespace sdk diff --git a/sdk/src/trace/async_batch_span_processor.cc b/sdk/src/trace/async_batch_span_processor.cc index 60fa7c370e..2aac7b55c2 100644 --- a/sdk/src/trace/async_batch_span_processor.cc +++ b/sdk/src/trace/async_batch_span_processor.cc @@ -19,21 +19,10 @@ namespace trace AsyncBatchSpanProcessor::AsyncBatchSpanProcessor(std::unique_ptr &&exporter, const AsyncBatchSpanProcessorOptions &options) - : exporter_(std::move(exporter)), - max_queue_size_(options.max_queue_size), - schedule_delay_millis_(options.schedule_delay_millis), - max_export_batch_size_(options.max_export_batch_size), + : BatchSpanProcessor(std::move(exporter), options.options), max_export_async_(options.max_export_async), - export_data_storage_(std::make_shared()), - buffer_(max_queue_size_), - synchronization_data_(std::make_shared()), - worker_thread_(&AsyncBatchSpanProcessor::DoBackgroundWork, this) + export_data_storage_(std::make_shared()) { - synchronization_data_->is_force_wakeup_background_worker.store(false); - synchronization_data_->is_force_flush_pending.store(false); - synchronization_data_->is_force_flush_notified.store(false); - synchronization_data_->is_shutdown.store(false); - export_data_storage_->export_ids_flag.resize(max_export_async_, true); for (size_t i = 1; i <= max_export_async_; i++) { @@ -41,144 +30,6 @@ AsyncBatchSpanProcessor::AsyncBatchSpanProcessor(std::unique_ptr & } } -std::unique_ptr AsyncBatchSpanProcessor::MakeRecordable() noexcept -{ - return exporter_->MakeRecordable(); -} - -void AsyncBatchSpanProcessor::OnStart(Recordable &, const SpanContext &) noexcept -{ - // no-op -} - -void AsyncBatchSpanProcessor::OnEnd(std::unique_ptr &&span) noexcept -{ - if (synchronization_data_->is_shutdown.load() == true) - { - return; - } - - if (buffer_.Add(span) == false) - { - return; - } - - // If the queue gets at least half full a preemptive notification is - // sent to the worker thread to start a new export cycle. - size_t buffer_size = buffer_.size(); - if (buffer_size >= max_queue_size_ / 2 || buffer_size >= max_export_batch_size_) - { - // signal the worker thread - synchronization_data_->cv.notify_one(); - } -} - -bool AsyncBatchSpanProcessor::ForceFlush(std::chrono::microseconds timeout) noexcept -{ - if (synchronization_data_->is_shutdown.load() == true) - { - return false; - } - - // Now wait for the worker thread to signal back from the Export method - std::unique_lock lk_cv(synchronization_data_->force_flush_cv_m); - - synchronization_data_->is_force_flush_pending.store(true, std::memory_order_release); - auto break_condition = [this]() { - if (synchronization_data_->is_shutdown.load() == true) - { - return true; - } - - // Wake up the worker thread once. - if (synchronization_data_->is_force_flush_pending.load(std::memory_order_acquire)) - { - synchronization_data_->is_force_wakeup_background_worker.store(true, - std::memory_order_release); - synchronization_data_->cv.notify_one(); - } - - return synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire); - }; - - // Fix timeout to meet requirement of wait_for - timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( - timeout, std::chrono::microseconds::zero()); - bool result; - if (timeout <= std::chrono::microseconds::zero()) - { - bool wait_result = false; - while (!wait_result) - { - // When is_force_flush_notified.store(true) and force_flush_cv.notify_all() is called - // between is_force_flush_pending.load() and force_flush_cv.wait(). We must not wait - // for ever - wait_result = synchronization_data_->force_flush_cv.wait_for(lk_cv, schedule_delay_millis_, - break_condition); - } - result = true; - } - else - { - result = synchronization_data_->force_flush_cv.wait_for(lk_cv, timeout, break_condition); - } - - // If it will be already signaled, we must wait util notified. - // We use a spin lock here - if (false == - synchronization_data_->is_force_flush_pending.exchange(false, std::memory_order_acq_rel)) - { - for (int retry_waiting_times = 0; - false == synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire); - ++retry_waiting_times) - { - opentelemetry::common::SpinLockMutex::fast_yield(); - if ((retry_waiting_times & 127) == 127) - { - std::this_thread::yield(); - } - } - } - synchronization_data_->is_force_flush_notified.store(false, std::memory_order_release); - - return result; -} - -void AsyncBatchSpanProcessor::DoBackgroundWork() -{ - auto timeout = schedule_delay_millis_; - - while (true) - { - // Wait for `timeout` milliseconds - std::unique_lock lk(synchronization_data_->cv_m); - synchronization_data_->cv.wait_for(lk, timeout, [this] { - if (synchronization_data_->is_force_wakeup_background_worker.load(std::memory_order_acquire)) - { - return true; - } - - return !buffer_.empty(); - }); - synchronization_data_->is_force_wakeup_background_worker.store(false, - std::memory_order_release); - - if (synchronization_data_->is_shutdown.load() == true) - { - DrainQueue(); - return; - } - - auto start = std::chrono::steady_clock::now(); - Export(); - auto end = std::chrono::steady_clock::now(); - auto duration = std::chrono::duration_cast(end - start); - - // Subtract the duration of this export call from the next `timeout`. - timeout = schedule_delay_millis_ - duration; - } -} - void AsyncBatchSpanProcessor::Export() { do @@ -199,7 +50,7 @@ void AsyncBatchSpanProcessor::Export() if (num_records_to_export == 0) { - NotifyCompletion(notify_force_flush, synchronization_data_); + NotifyCompletion(notify_force_flush, synchronization_data_, export_data_storage_); break; } buffer_.Consume(num_records_to_export, @@ -214,8 +65,8 @@ void AsyncBatchSpanProcessor::Export() size_t id = kInvalidExportId; { - std::unique_lock lock(synchronization_data_->async_export_data_m); - synchronization_data_->async_export_waker.wait_for(lock, schedule_delay_millis_, [this] { + std::unique_lock lock(export_data_storage_->async_export_data_m); + export_data_storage_->async_export_waker.wait_for(lock, schedule_delay_millis_, [this] { return export_data_storage_->export_ids.size() > 0; }); if (export_data_storage_->export_ids.size() > 0) @@ -248,14 +99,14 @@ void AsyncBatchSpanProcessor::Export() auto synchronization_data = synchronization_data_watcher.lock(); auto export_data = export_data_watcher.lock(); { - std::unique_lock lk(synchronization_data->async_export_data_m); + std::unique_lock lk(export_data->async_export_data_m); if (export_data->export_ids_flag[id - 1] == false) { export_data->export_ids.push(id); export_data->export_ids_flag[id - 1] = true; } } - NotifyCompletion(notify_force_flush, synchronization_data); + NotifyCompletion(notify_force_flush, synchronization_data, export_data); return true; }); } @@ -264,54 +115,11 @@ void AsyncBatchSpanProcessor::Export() void AsyncBatchSpanProcessor::NotifyCompletion( bool notify_force_flush, - const std::shared_ptr &synchronization_data) -{ - if (!synchronization_data) - { - return; - } - - if (notify_force_flush) - { - synchronization_data->is_force_flush_notified.store(true, std::memory_order_release); - synchronization_data->force_flush_cv.notify_one(); - } - - synchronization_data->async_export_waker.notify_all(); -} - -void AsyncBatchSpanProcessor::DrainQueue() -{ - while (true) - { - if (buffer_.empty() && - false == synchronization_data_->is_force_flush_pending.load(std::memory_order_acquire)) - { - break; - } - - Export(); - } -} - -void AsyncBatchSpanProcessor::GetWaitAdjustedTime( - std::chrono::microseconds &timeout, - std::chrono::time_point &start_time) + const std::shared_ptr &synchronization_data, + const std::shared_ptr &export_data_storage) { - auto end_time = std::chrono::system_clock::now(); - auto offset = std::chrono::duration_cast(end_time - start_time); - start_time = end_time; - timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( - timeout, std::chrono::microseconds::zero()); - if (timeout > offset && timeout > std::chrono::microseconds::zero()) - { - timeout -= offset; - } - else - { - // Some module use zero as indefinite timeout.So we can not reset timeout to zero here - timeout = std::chrono::microseconds(1); - } + BatchSpanProcessor::NotifyCompletion(notify_force_flush, synchronization_data); + export_data_storage->async_export_waker.notify_all(); } bool AsyncBatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexcept @@ -330,8 +138,8 @@ bool AsyncBatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexce GetWaitAdjustedTime(timeout, start_time); // wait for all async exports to complete and return if timeout reached. { - std::unique_lock lock(synchronization_data_->async_export_data_m); - synchronization_data_->async_export_waker.wait_for(lock, timeout, [this] { + std::unique_lock lock(export_data_storage_->async_export_data_m); + export_data_storage_->async_export_waker.wait_for(lock, timeout, [this] { return export_data_storage_->export_ids.size() == max_export_async_; }); } @@ -346,13 +154,7 @@ bool AsyncBatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexce return true; } -AsyncBatchSpanProcessor::~AsyncBatchSpanProcessor() -{ - if (synchronization_data_->is_shutdown.load() == false) - { - Shutdown(); - } -} +AsyncBatchSpanProcessor::~AsyncBatchSpanProcessor() {} } // namespace trace } // namespace sdk diff --git a/sdk/test/logs/async_batch_log_processor_test.cc b/sdk/test/logs/async_batch_log_processor_test.cc index 1a4f024217..280ec0d55e 100644 --- a/sdk/test/logs/async_batch_log_processor_test.cc +++ b/sdk/test/logs/async_batch_log_processor_test.cc @@ -133,10 +133,15 @@ class AsyncBatchLogProcessorTest : public testing::Test // ::testing::Test const size_t max_export_async = 8, int callback_count = 1) { + AsyncBatchLogProcessorOptions options; + options.options.max_queue_size = max_queue_size; + options.options.schedule_delay_millis = scheduled_delay_millis; + options.options.max_export_batch_size = max_export_batch_size; + options.max_export_async = max_export_async; return std::shared_ptr(new AsyncBatchLogProcessor( std::unique_ptr(new MockLogExporter( logs_received, is_shutdown, is_export_completed, export_delay, callback_count)), - max_queue_size, scheduled_delay_millis, max_export_batch_size, max_export_async)); + options)); } }; @@ -152,12 +157,11 @@ TEST_F(AsyncBatchLogProcessorTest, TestAsyncShutdown) const std::chrono::milliseconds scheduled_delay_millis(5000); const size_t max_export_batch_size = 512; const size_t max_queue_size = 2048; - const bool is_export_async = true; const size_t max_export_async = 5; auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, export_delay, scheduled_delay_millis, max_queue_size, - max_export_batch_size, is_export_async, max_export_async); + max_export_batch_size, max_export_async); // Create a few test log records and send them to the processor const int num_logs = 2048; @@ -200,7 +204,6 @@ TEST_F(AsyncBatchLogProcessorTest, TestAsyncShutdownNoCallback) const std::chrono::milliseconds scheduled_delay_millis(5000); const size_t max_export_batch_size = 512; const size_t max_queue_size = 2048; - const bool is_export_async = true; const size_t max_export_async = 5; auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, @@ -236,7 +239,6 @@ TEST_F(AsyncBatchLogProcessorTest, TestAsyncForceFlush) const std::chrono::milliseconds scheduled_delay_millis(5000); const size_t max_export_batch_size = 512; const size_t max_queue_size = 2048; - const bool is_export_async = true; auto batch_processor = GetMockProcessor(logs_received, is_shutdown, is_export_completed, export_delay, diff --git a/sdk/test/trace/async_batch_span_processor_test.cc b/sdk/test/trace/async_batch_span_processor_test.cc index 1ac28c5bc9..787b8def68 100644 --- a/sdk/test/trace/async_batch_span_processor_test.cc +++ b/sdk/test/trace/async_batch_span_processor_test.cc @@ -340,7 +340,7 @@ TEST_F(AsyncBatchSpanProcessorTestPeer, TestScheduleDelayMillis) const std::chrono::milliseconds export_delay(0); const size_t max_export_batch_size = 512; sdk::trace::AsyncBatchSpanProcessorOptions options{}; - options.schedule_delay_millis = std::chrono::milliseconds(2000); + options.options.schedule_delay_millis = std::chrono::milliseconds(2000); auto batch_processor = std::shared_ptr(new sdk::trace::AsyncBatchSpanProcessor( @@ -356,7 +356,7 @@ TEST_F(AsyncBatchSpanProcessorTestPeer, TestScheduleDelayMillis) } // Sleep for schedule_delay_millis milliseconds - std::this_thread::sleep_for(options.schedule_delay_millis); + std::this_thread::sleep_for(options.options.schedule_delay_millis); // small delay to give time to export std::this_thread::sleep_for(std::chrono::milliseconds(50)); From ca556b1170deea2f305c5da9b8e167f4735bfc1b Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Mon, 25 Apr 2022 11:43:44 +0530 Subject: [PATCH 08/10] Incorporated some review comments --- CMakeLists.txt | 4 ---- exporters/otlp/test/otlp_http_exporter_test.cc | 12 ++++++------ exporters/otlp/test/otlp_http_log_exporter_test.cc | 12 ++++++------ .../sdk/logs/async_batch_log_processor.h | 6 ++---- .../opentelemetry/sdk/logs/batch_log_processor.h | 10 +++++----- .../sdk/trace/async_batch_span_processor.h | 6 ++---- .../opentelemetry/sdk/trace/batch_span_processor.h | 10 +++++----- sdk/src/logs/async_batch_log_processor.cc | 10 ++++++++-- sdk/src/trace/async_batch_span_processor.cc | 10 ++++++++-- sdk/test/logs/async_batch_log_processor_test.cc | 6 +++--- sdk/test/trace/async_batch_span_processor_test.cc | 4 ++-- 11 files changed, 47 insertions(+), 43 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index efc63249e1..e30a1080fc 100755 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -228,10 +228,6 @@ endif() option(WITH_ASYNC_EXPORT_PREVIEW "Whether enable async export" OFF) -if(WITH_ASYNC_EXPORT_PREVIEW) - add_definitions(-DENABLE_ASYNC_EXPORT) -endif() - find_package(Threads) function(install_windows_deps) diff --git a/exporters/otlp/test/otlp_http_exporter_test.cc b/exporters/otlp/test/otlp_http_exporter_test.cc index 4e4f8f706c..83d5cc8d17 100644 --- a/exporters/otlp/test/otlp_http_exporter_test.cc +++ b/exporters/otlp/test/otlp_http_exporter_test.cc @@ -197,9 +197,9 @@ class OtlpHttpExporterTestPeer : public ::testing::Test auto resource = resource::Resource::Create(resource_attributes); auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); - processor_opts.options.max_export_batch_size = 5; - processor_opts.options.max_queue_size = 5; - processor_opts.options.schedule_delay_millis = std::chrono::milliseconds(256); + processor_opts.max_export_batch_size = 5; + processor_opts.max_queue_size = 5; + processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); auto processor = std::unique_ptr( new sdk::trace::AsyncBatchSpanProcessor(std::move(exporter), processor_opts)); @@ -367,9 +367,9 @@ class OtlpHttpExporterTestPeer : public ::testing::Test auto resource = resource::Resource::Create(resource_attributes); auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); - processor_opts.options.max_export_batch_size = 5; - processor_opts.options.max_queue_size = 5; - processor_opts.options.schedule_delay_millis = std::chrono::milliseconds(256); + processor_opts.max_export_batch_size = 5; + processor_opts.max_queue_size = 5; + processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); auto processor = std::unique_ptr( new sdk::trace::AsyncBatchSpanProcessor(std::move(exporter), processor_opts)); diff --git a/exporters/otlp/test/otlp_http_log_exporter_test.cc b/exporters/otlp/test/otlp_http_log_exporter_test.cc index 340a3c746c..bdeedf95e8 100644 --- a/exporters/otlp/test/otlp_http_log_exporter_test.cc +++ b/exporters/otlp/test/otlp_http_log_exporter_test.cc @@ -201,9 +201,9 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); sdk::logs::AsyncBatchLogProcessorOptions options; - options.options.max_queue_size = 5; - options.options.schedule_delay_millis = std::chrono::milliseconds(256); - options.options.max_export_batch_size = 5; + options.max_queue_size = 5; + options.schedule_delay_millis = std::chrono::milliseconds(256); + options.max_export_batch_size = 5; provider->AddProcessor(std::unique_ptr( new sdk::logs::AsyncBatchLogProcessor(std::move(exporter), options))); @@ -401,9 +401,9 @@ class OtlpHttpLogExporterTestPeer : public ::testing::Test auto provider = nostd::shared_ptr(new sdk::logs::LoggerProvider()); sdk::logs::AsyncBatchLogProcessorOptions processor_options; - processor_options.options.max_export_batch_size = 5; - processor_options.options.max_queue_size = 5; - processor_options.options.schedule_delay_millis = std::chrono::milliseconds(256); + processor_options.max_export_batch_size = 5; + processor_options.max_queue_size = 5; + processor_options.schedule_delay_millis = std::chrono::milliseconds(256); provider->AddProcessor(std::unique_ptr( new sdk::logs::AsyncBatchLogProcessor(std::move(exporter), processor_options))); diff --git a/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h index a307c68a69..2ba9ac686d 100644 --- a/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h @@ -26,10 +26,8 @@ namespace logs /** * Struct to hold batch SpanProcessor options. */ -struct AsyncBatchLogProcessorOptions +struct AsyncBatchLogProcessorOptions: public BatchLogProcessorOptions { - BatchLogProcessorOptions options; - /* Denotes the maximum number of async exports to continue */ size_t max_export_async = 8; @@ -65,7 +63,7 @@ class AsyncBatchLogProcessor : public BatchLogProcessor /** * Class destructor which invokes the Shutdown() method. */ - virtual ~AsyncBatchLogProcessor() override; + virtual ~AsyncBatchLogProcessor(); private: /** diff --git a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h index 1ddc518137..2a781b937c 100644 --- a/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/batch_log_processor.h @@ -77,21 +77,21 @@ class BatchLogProcessor : public LogProcessor const BatchLogProcessorOptions &options); /** Makes a new recordable **/ - virtual std::unique_ptr MakeRecordable() noexcept override; + std::unique_ptr MakeRecordable() noexcept override; /** * Called when the Logger's log method creates a log record * @param record the log record */ - virtual void OnReceive(std::unique_ptr &&record) noexcept override; + void OnReceive(std::unique_ptr &&record) noexcept override; /** * Export all log records that have not been exported yet. * * NOTE: Timeout functionality not supported yet. */ - virtual bool ForceFlush( + bool ForceFlush( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; /** @@ -101,13 +101,13 @@ class BatchLogProcessor : public LogProcessor * * NOTE: Timeout functionality not supported yet. */ - virtual bool Shutdown( + bool Shutdown( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; /** * Class destructor which invokes the Shutdown() method. */ - virtual ~BatchLogProcessor() override; + virtual ~BatchLogProcessor(); protected: /** diff --git a/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h index 03801f41dc..7f481fcde0 100644 --- a/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h @@ -23,10 +23,8 @@ namespace trace /** * Struct to hold batch SpanProcessor options. */ -struct AsyncBatchSpanProcessorOptions +struct AsyncBatchSpanProcessorOptions: public BatchSpanProcessorOptions { - BatchSpanProcessorOptions options; - /* Denotes the maximum number of async exports to continue */ size_t max_export_async = 8; @@ -65,7 +63,7 @@ class AsyncBatchSpanProcessor : public BatchSpanProcessor * shared ownership of the processor, and thus doesn't call Shutdown (as the processor might be * shared with other Tracers). */ - virtual ~AsyncBatchSpanProcessor() override; + virtual ~AsyncBatchSpanProcessor(); private: /** diff --git a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h index 8f61d0ffc8..4e10cacdf2 100644 --- a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h @@ -61,7 +61,7 @@ class BatchSpanProcessor : public SpanProcessor * * @return A recordable generated by the backend exporter */ - virtual std::unique_ptr MakeRecordable() noexcept override; + std::unique_ptr MakeRecordable() noexcept override; /** * Called when a span is started. @@ -71,7 +71,7 @@ class BatchSpanProcessor : public SpanProcessor * @param span - The span that just started * @param parent_context - The parent context of the span that just started */ - virtual void OnStart(Recordable &span, + void OnStart(Recordable &span, const opentelemetry::trace::SpanContext &parent_context) noexcept override; /** @@ -79,14 +79,14 @@ class BatchSpanProcessor : public SpanProcessor * * @param span - A recordable for a span that just ended */ - virtual void OnEnd(std::unique_ptr &&span) noexcept override; + void OnEnd(std::unique_ptr &&span) noexcept override; /** * Export all ended spans that have not been exported yet. * * NOTE: Timeout functionality not supported yet. */ - virtual bool ForceFlush( + bool ForceFlush( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; /** @@ -96,7 +96,7 @@ class BatchSpanProcessor : public SpanProcessor * * NOTE: Timeout functionality not supported yet. */ - virtual bool Shutdown( + bool Shutdown( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override; /** diff --git a/sdk/src/logs/async_batch_log_processor.cc b/sdk/src/logs/async_batch_log_processor.cc index f266ea0b44..fff7364376 100644 --- a/sdk/src/logs/async_batch_log_processor.cc +++ b/sdk/src/logs/async_batch_log_processor.cc @@ -17,7 +17,7 @@ namespace logs { AsyncBatchLogProcessor::AsyncBatchLogProcessor(std::unique_ptr &&exporter, const AsyncBatchLogProcessorOptions &options) - : BatchLogProcessor(std::move(exporter), options.options), + : BatchLogProcessor(std::move(exporter), options), max_export_async_(options.max_export_async), export_data_storage_(std::make_shared()) { @@ -161,7 +161,13 @@ bool AsyncBatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcep return true; } -AsyncBatchLogProcessor::~AsyncBatchLogProcessor() {} +AsyncBatchLogProcessor::~AsyncBatchLogProcessor() +{ + if (synchronization_data_->is_shutdown.load() == false) + { + Shutdown(); + } +} } // namespace logs } // namespace sdk diff --git a/sdk/src/trace/async_batch_span_processor.cc b/sdk/src/trace/async_batch_span_processor.cc index 2aac7b55c2..ec42c8d379 100644 --- a/sdk/src/trace/async_batch_span_processor.cc +++ b/sdk/src/trace/async_batch_span_processor.cc @@ -19,7 +19,7 @@ namespace trace AsyncBatchSpanProcessor::AsyncBatchSpanProcessor(std::unique_ptr &&exporter, const AsyncBatchSpanProcessorOptions &options) - : BatchSpanProcessor(std::move(exporter), options.options), + : BatchSpanProcessor(std::move(exporter), options), max_export_async_(options.max_export_async), export_data_storage_(std::make_shared()) { @@ -154,7 +154,13 @@ bool AsyncBatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexce return true; } -AsyncBatchSpanProcessor::~AsyncBatchSpanProcessor() {} +AsyncBatchSpanProcessor::~AsyncBatchSpanProcessor() +{ + if (synchronization_data_->is_shutdown.load() == false) + { + Shutdown(); + } +} } // namespace trace } // namespace sdk diff --git a/sdk/test/logs/async_batch_log_processor_test.cc b/sdk/test/logs/async_batch_log_processor_test.cc index 280ec0d55e..25ccea291c 100644 --- a/sdk/test/logs/async_batch_log_processor_test.cc +++ b/sdk/test/logs/async_batch_log_processor_test.cc @@ -134,9 +134,9 @@ class AsyncBatchLogProcessorTest : public testing::Test // ::testing::Test int callback_count = 1) { AsyncBatchLogProcessorOptions options; - options.options.max_queue_size = max_queue_size; - options.options.schedule_delay_millis = scheduled_delay_millis; - options.options.max_export_batch_size = max_export_batch_size; + options.max_queue_size = max_queue_size; + options.schedule_delay_millis = scheduled_delay_millis; + options.max_export_batch_size = max_export_batch_size; options.max_export_async = max_export_async; return std::shared_ptr(new AsyncBatchLogProcessor( std::unique_ptr(new MockLogExporter( diff --git a/sdk/test/trace/async_batch_span_processor_test.cc b/sdk/test/trace/async_batch_span_processor_test.cc index 787b8def68..1ac28c5bc9 100644 --- a/sdk/test/trace/async_batch_span_processor_test.cc +++ b/sdk/test/trace/async_batch_span_processor_test.cc @@ -340,7 +340,7 @@ TEST_F(AsyncBatchSpanProcessorTestPeer, TestScheduleDelayMillis) const std::chrono::milliseconds export_delay(0); const size_t max_export_batch_size = 512; sdk::trace::AsyncBatchSpanProcessorOptions options{}; - options.options.schedule_delay_millis = std::chrono::milliseconds(2000); + options.schedule_delay_millis = std::chrono::milliseconds(2000); auto batch_processor = std::shared_ptr(new sdk::trace::AsyncBatchSpanProcessor( @@ -356,7 +356,7 @@ TEST_F(AsyncBatchSpanProcessorTestPeer, TestScheduleDelayMillis) } // Sleep for schedule_delay_millis milliseconds - std::this_thread::sleep_for(options.options.schedule_delay_millis); + std::this_thread::sleep_for(options.schedule_delay_millis); // small delay to give time to export std::this_thread::sleep_for(std::chrono::milliseconds(50)); From c2c58604868a26eeb46fb452f65716f574dd1e42 Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Mon, 25 Apr 2022 12:19:04 +0530 Subject: [PATCH 09/10] Fixed Format --- exporters/otlp/test/otlp_http_exporter_test.cc | 4 ++-- .../opentelemetry/sdk/logs/async_batch_log_processor.h | 2 +- .../opentelemetry/sdk/trace/async_batch_span_processor.h | 2 +- sdk/include/opentelemetry/sdk/trace/batch_span_processor.h | 2 +- sdk/test/logs/async_batch_log_processor_test.cc | 2 +- 5 files changed, 6 insertions(+), 6 deletions(-) diff --git a/exporters/otlp/test/otlp_http_exporter_test.cc b/exporters/otlp/test/otlp_http_exporter_test.cc index 83d5cc8d17..c25c0111b2 100644 --- a/exporters/otlp/test/otlp_http_exporter_test.cc +++ b/exporters/otlp/test/otlp_http_exporter_test.cc @@ -196,7 +196,7 @@ class OtlpHttpExporterTestPeer : public ::testing::Test resource_attributes["vec_string_value"] = std::vector{"vector", "string"}; auto resource = resource::Resource::Create(resource_attributes); - auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); + auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); processor_opts.max_export_batch_size = 5; processor_opts.max_queue_size = 5; processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); @@ -366,7 +366,7 @@ class OtlpHttpExporterTestPeer : public ::testing::Test resource_attributes["vec_string_value"] = std::vector{"vector", "string"}; auto resource = resource::Resource::Create(resource_attributes); - auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); + auto processor_opts = sdk::trace::AsyncBatchSpanProcessorOptions(); processor_opts.max_export_batch_size = 5; processor_opts.max_queue_size = 5; processor_opts.schedule_delay_millis = std::chrono::milliseconds(256); diff --git a/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h b/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h index 2ba9ac686d..7cc6af8738 100644 --- a/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h +++ b/sdk/include/opentelemetry/sdk/logs/async_batch_log_processor.h @@ -26,7 +26,7 @@ namespace logs /** * Struct to hold batch SpanProcessor options. */ -struct AsyncBatchLogProcessorOptions: public BatchLogProcessorOptions +struct AsyncBatchLogProcessorOptions : public BatchLogProcessorOptions { /* Denotes the maximum number of async exports to continue */ diff --git a/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h index 7f481fcde0..4cbb234e71 100644 --- a/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/async_batch_span_processor.h @@ -23,7 +23,7 @@ namespace trace /** * Struct to hold batch SpanProcessor options. */ -struct AsyncBatchSpanProcessorOptions: public BatchSpanProcessorOptions +struct AsyncBatchSpanProcessorOptions : public BatchSpanProcessorOptions { /* Denotes the maximum number of async exports to continue */ diff --git a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h index 4e10cacdf2..f18fc78346 100644 --- a/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h +++ b/sdk/include/opentelemetry/sdk/trace/batch_span_processor.h @@ -72,7 +72,7 @@ class BatchSpanProcessor : public SpanProcessor * @param parent_context - The parent context of the span that just started */ void OnStart(Recordable &span, - const opentelemetry::trace::SpanContext &parent_context) noexcept override; + const opentelemetry::trace::SpanContext &parent_context) noexcept override; /** * Called when a span ends. diff --git a/sdk/test/logs/async_batch_log_processor_test.cc b/sdk/test/logs/async_batch_log_processor_test.cc index 25ccea291c..dba600b9a7 100644 --- a/sdk/test/logs/async_batch_log_processor_test.cc +++ b/sdk/test/logs/async_batch_log_processor_test.cc @@ -137,7 +137,7 @@ class AsyncBatchLogProcessorTest : public testing::Test // ::testing::Test options.max_queue_size = max_queue_size; options.schedule_delay_millis = scheduled_delay_millis; options.max_export_batch_size = max_export_batch_size; - options.max_export_async = max_export_async; + options.max_export_async = max_export_async; return std::shared_ptr(new AsyncBatchLogProcessor( std::unique_ptr(new MockLogExporter( logs_received, is_shutdown, is_export_completed, export_delay, callback_count)), From f5324c9015593e4e127ff2bafb962801ba7f865c Mon Sep 17 00:00:00 2001 From: DebajitDas Date: Thu, 28 Apr 2022 20:28:05 +0530 Subject: [PATCH 10/10] Incorporated Review Comments --- sdk/src/logs/async_batch_log_processor.cc | 28 +++++++++++++++++---- sdk/src/trace/async_batch_span_processor.cc | 27 +++++++++++++++++--- 2 files changed, 46 insertions(+), 9 deletions(-) diff --git a/sdk/src/logs/async_batch_log_processor.cc b/sdk/src/logs/async_batch_log_processor.cc index fff7364376..5d99754c12 100644 --- a/sdk/src/logs/async_batch_log_processor.cc +++ b/sdk/src/logs/async_batch_log_processor.cc @@ -7,6 +7,7 @@ # include "opentelemetry/common/spin_lock_mutex.h" # include + using opentelemetry::sdk::common::AtomicUniquePtr; using opentelemetry::sdk::common::CircularBufferRange; @@ -130,11 +131,14 @@ void AsyncBatchLogProcessor::NotifyCompletion( bool AsyncBatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcept { + if (synchronization_data_->is_shutdown.load() == true) + { + return true; + } auto start_time = std::chrono::system_clock::now(); std::lock_guard shutdown_guard{synchronization_data_->shutdown_m}; bool already_shutdown = synchronization_data_->is_shutdown.exchange(true); - if (worker_thread_.joinable()) { synchronization_data_->is_force_wakeup_background_worker.store(true, std::memory_order_release); @@ -142,13 +146,27 @@ bool AsyncBatchLogProcessor::Shutdown(std::chrono::microseconds timeout) noexcep worker_thread_.join(); } - GetWaitAdjustedTime(timeout, start_time); + timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( + timeout, std::chrono::microseconds::zero()); // wait for all async exports to complete and return if timeout reached. { std::unique_lock lock(export_data_storage_->async_export_data_m); - export_data_storage_->async_export_waker.wait_for(lock, timeout, [this] { - return export_data_storage_->export_ids.size() == max_export_async_; - }); + if (timeout <= std::chrono::microseconds::zero()) + { + auto is_wait = false; + while (!is_wait) + { + is_wait = export_data_storage_->async_export_waker.wait_for( + lock, scheduled_delay_millis_, + [this] { return export_data_storage_->export_ids.size() == max_export_async_; }); + } + } + else + { + export_data_storage_->async_export_waker.wait_for(lock, timeout, [this] { + return export_data_storage_->export_ids.size() == max_export_async_; + }); + } } GetWaitAdjustedTime(timeout, start_time); diff --git a/sdk/src/trace/async_batch_span_processor.cc b/sdk/src/trace/async_batch_span_processor.cc index ec42c8d379..4f7a7c957a 100644 --- a/sdk/src/trace/async_batch_span_processor.cc +++ b/sdk/src/trace/async_batch_span_processor.cc @@ -124,6 +124,11 @@ void AsyncBatchSpanProcessor::NotifyCompletion( bool AsyncBatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexcept { + if (synchronization_data_->is_shutdown.load() == true) + { + return true; + } + auto start_time = std::chrono::system_clock::now(); std::lock_guard shutdown_guard{synchronization_data_->shutdown_m}; bool already_shutdown = synchronization_data_->is_shutdown.exchange(true); @@ -135,13 +140,27 @@ bool AsyncBatchSpanProcessor::Shutdown(std::chrono::microseconds timeout) noexce worker_thread_.join(); } - GetWaitAdjustedTime(timeout, start_time); + timeout = opentelemetry::common::DurationUtil::AdjustWaitForTimeout( + timeout, std::chrono::microseconds::zero()); // wait for all async exports to complete and return if timeout reached. { std::unique_lock lock(export_data_storage_->async_export_data_m); - export_data_storage_->async_export_waker.wait_for(lock, timeout, [this] { - return export_data_storage_->export_ids.size() == max_export_async_; - }); + if (timeout <= std::chrono::microseconds::zero()) + { + auto is_wait = false; + while (!is_wait) + { + is_wait = export_data_storage_->async_export_waker.wait_for( + lock, schedule_delay_millis_, + [this] { return export_data_storage_->export_ids.size() == max_export_async_; }); + } + } + else + { + export_data_storage_->async_export_waker.wait_for(lock, timeout, [this] { + return export_data_storage_->export_ids.size() == max_export_async_; + }); + } } GetWaitAdjustedTime(timeout, start_time);