diff --git a/.pkg b/.pkg index 0c5fcd0ea..fa81983e3 100644 --- a/.pkg +++ b/.pkg @@ -69,7 +69,7 @@ [boost] url=git@github.com:motis-project/boost.git branch=master - commit=1c3f21c1fa8b149da89e2f6bcb48b28fff30fa5e + commit=60cae66449fa3c9599b2b7d3d5d44c65301ed3a3 [mimalloc] url=git@github.com:motis-project/mimalloc.git branch=master @@ -77,7 +77,7 @@ [nigiri] url=git@github.com:motis-project/nigiri.git branch=master - commit=ada780c39ab11cfd6a1dd6e8b972f6b877f07d1b + commit=d6e1c8f5c0a8264e568fa85a34622e105a975315 [osr] url=git@github.com:motis-project/osr.git branch=master @@ -86,3 +86,11 @@ url=git@github.com:triptix-tech/adr.git branch=master commit=bef3f11a8c1642939e7047bcebf3d2f3528b23a3 +[prometheus-cpp] + url=git@github.com:motis-project/prometheus-cpp.git + branch=master + commit=e420cd7cf3995a994220b40a36c987ac8e67c0bf +[opentelemetry-cpp] + url=git@github.com:motis-project/opentelemetry-cpp.git + branch=main + commit=ec4aef6b17b697052edef5417825ad71947b2ed1 diff --git a/.pkg.lock b/.pkg.lock index 9d27028e6..c4d1a358b 100644 --- a/.pkg.lock +++ b/.pkg.lock @@ -1,6 +1,6 @@ -5392555982345106832 +2672259012793768236 cista f52a62c4d83377acd398227ab4fcd6c946bdbd70 -zlib fe8e13ffca867612951bc6baf114e5ac8b00f305 +zlib ee0742244d93c4237154ae16c3db42b5f284b442 boost 60cae66449fa3c9599b2b7d3d5d44c65301ed3a3 conf f9bf4bd83bf55a2170725707e526cbacc45dcc66 context 797dd16e2b5e959997ddcd5bdeac4f80931169b6 @@ -18,15 +18,19 @@ guess cecba85dbd6796c92a7f9c4e274849bb6ef03494 lmdb 9bd01f14f549d8202413c4cd5f49b066b0a22b66 mimalloc 2a557cafb2e9e7c872358a83a63c62a7e14330b3 miniz 1edbdece9d71dc65c6ff405572ee37cbdcef7af4 -libressl 39c1bf084d5c179d7bbce7ba902fffbebff0ee15 +libressl 24acd9e710fbe842e863572da9d738715fbc74b8 net 785b39c08212732e510305f0eef18de70f19b15e PEGTL 1c1aa6e650e4d26f10fa398f148ec0cdc5f0808d oh d21c30f40e52a83d6dc09bcffd0067598b5ec069 +curl 3358dac21192864ef2ba47c88704d3b8d8203804 +json 410c74782230daaa15054d6ee0975c0607091cb3 +opentelemetry-proto 1624689398a3226c45994d70cb544a1e781dc032 abseil-cpp ba5240842d352b4b67a32092453a2fe5fe53a62e protobuf d8136b9c6a62db6ce09900ecdeb82bb793096cbd +opentelemetry-cpp ec4aef6b17b697052edef5417825ad71947b2ed1 unordered_dense c11595a7743d20622637584bddf77243d72ae152 wyhash 1e012b57fc2227a9e583a57e2eacb3da99816d99 -nigiri ada780c39ab11cfd6a1dd6e8b972f6b877f07d1b +nigiri d6e1c8f5c0a8264e568fa85a34622e105a975315 expat 636c9861e8e7c119f3626d1e6c260603ab624516 libosmium d5cc2a02d997c2b464d37d37c3a75cd9efa23dc4 protozero 8c9f3fa97c2cfdceef86d0b61818ae98e9328f29 @@ -45,6 +49,7 @@ tbb b3011be5060ec1be43c76d4a8cc80d5550adb31d osrm-backend 40975002f31c4f1eaa623880efaf579c6007edf9 cpptoml 2133029ec819e8398e96fa679993b269f21ff9f2 ppr 512cfefe0fe7c7a64ef0adefbf7af2adfe5200c4 +prometheus-cpp e420cd7cf3995a994220b40a36c987ac8e67c0bf FTXUI dd6a5d371fd7a3e2937bb579955003c54b727233 tg 20c0f298b8ce58de29a790290f44dca7c4ecc364 adr bef3f11a8c1642939e7047bcebf3d2f3528b23a3 diff --git a/CMakeLists.txt b/CMakeLists.txt index 985cd209b..ea0e628ea 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -3,6 +3,8 @@ project(motis) enable_language(CXX C ASM) +set(CMAKE_POLICY_DEFAULT_CMP0077 NEW) + if (MSVC) # PDB debug information is not supported by buildcache. # Store debug info in the object files. @@ -46,8 +48,10 @@ option(MOTIS_WITH_WEBUI "enable motis-web-ui target" OFF) if(NOT DEFINED CMAKE_MSVC_RUNTIME_LIBRARY) if(MOTIS_MIMALLOC) set(CMAKE_MSVC_RUNTIME_LIBRARY "MultiThreaded$<$:Debug>DLL") + set(protobuf_MSVC_STATIC_RUNTIME OFF) else() set(CMAKE_MSVC_RUNTIME_LIBRARY "MultiThreaded$<$:Debug>") + set(protobuf_MSVC_STATIC_RUNTIME ON) endif() endif() @@ -239,6 +243,7 @@ target_link_libraries(motis ianatzdb-res pbf_sdf_fonts_res-res tiles_server_res-res + opentelemetry_exporter_otlp_http ) target_compile_options(motis PRIVATE ${MOTIS_CXX_FLAGS}) set_target_properties(motis PROPERTIES RUNTIME_OUTPUT_DIRECTORY "${CMAKE_BINARY_DIR}") diff --git a/CMakePresets.json b/CMakePresets.json index b02de0169..17c1dce40 100644 --- a/CMakePresets.json +++ b/CMakePresets.json @@ -257,4 +257,4 @@ "configurePreset": "linux-sanitizer" } ] -} \ No newline at end of file +} diff --git a/base/bootstrap/CMakeLists.txt b/base/bootstrap/CMakeLists.txt index 6eeb00155..552a06716 100644 --- a/base/bootstrap/CMakeLists.txt +++ b/base/bootstrap/CMakeLists.txt @@ -26,4 +26,11 @@ add_library(motis-bootstrap STATIC ${motis-bootstrap-files}) target_include_directories(motis-bootstrap PUBLIC include) target_compile_features(motis-bootstrap PUBLIC cxx_std_17) target_compile_options(motis-bootstrap PRIVATE ${MOTIS_CXX_FLAGS}) -target_link_libraries(motis-bootstrap conf utl motis-module ${module-targets}) +target_link_libraries(motis-bootstrap + conf + utl + prometheus-cpp::core + opentelemetry_trace + motis-module + ${module-targets} +) diff --git a/base/bootstrap/src/motis_instance.cc b/base/bootstrap/src/motis_instance.cc index a7c5c3b52..361722f4b 100644 --- a/base/bootstrap/src/motis_instance.cc +++ b/base/bootstrap/src/motis_instance.cc @@ -4,15 +4,22 @@ #include #include #include +#include +#include "fmt/format.h" #include "fmt/ranges.h" +#include "prometheus/registry.h" + +#include "opentelemetry/trace/tracer.h" + #include "utl/pipes.h" #include "utl/progress_tracker.h" #include "utl/raii.h" #include "utl/verify.h" #include "motis/core/common/logging.h" +#include "motis/core/otel/tracer.h" #include "motis/module/context/motis_call.h" #include "motis/module/context/motis_publish.h" #include "motis/bootstrap/import_files.h" @@ -25,6 +32,8 @@ using namespace motis::logging; namespace motis::bootstrap { motis_instance::motis_instance() : controller{build_modules()} { + emplace_data(to_res_id(global_res_id::METRICS), + std::make_shared()); for (auto& m : modules_) { m->set_shared_data(this); } @@ -66,6 +75,9 @@ void motis_instance::import(module_settings const& module_opt, bool const silent) { auto bars = utl::global_progress_bars{silent}; + auto span = motis_tracer->StartSpan("import"); + auto scope = opentelemetry::trace::Scope{span}; + auto dispatcher = import_dispatcher{}; register_import_files(dispatcher); @@ -103,23 +115,39 @@ void motis_instance::import(module_settings const& module_opt, void motis_instance::init_modules(module_settings const& module_opt, unsigned num_threads) { + auto outer_span = motis_tracer->StartSpan("init_modules"); + auto outer_scope = opentelemetry::trace::Scope{outer_span}; + for (auto const& module : modules_) { if (!module_opt.is_module_active(module->prefix())) { continue; } + auto span = + motis_tracer->StartSpan(fmt::format("init {}", module->module_name())); + auto scope = opentelemetry::trace::Scope{outer_span}; + if (!module->import_successful()) { LOG(info) << module->module_name() << ": import was not successful"; + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "import failed"); continue; } try { module->init(registry_); } catch (std::exception const& e) { + span->AddEvent("exception", { + {"exception.message", e.what()}, + }); + span->SetStatus(opentelemetry::trace::StatusCode::kError, "exception"); LOG(emrg) << "module " << module->module_name() << ": unhandled init error: " << e.what(); throw; } catch (...) { + span->AddEvent("exception", {{"exception.type", "unknown"}}); + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "unknown error"); LOG(emrg) << "module " << module->module_name() << "unhandled unknown init error"; throw; diff --git a/base/core/CMakeLists.txt b/base/core/CMakeLists.txt index 54916cdf5..f88a267c9 100644 --- a/base/core/CMakeLists.txt +++ b/base/core/CMakeLists.txt @@ -13,4 +13,5 @@ target_link_libraries(motis-core geo motis-data motis-module + opentelemetry_api ) diff --git a/base/core/include/motis/core/common/timing.h b/base/core/include/motis/core/common/timing.h index 965f8c218..74c3c5ab4 100644 --- a/base/core/include/motis/core/common/timing.h +++ b/base/core/include/motis/core/common/timing.h @@ -5,15 +5,27 @@ #define MOTIS_START_TIMING(_X) \ auto _X##_start = std::chrono::steady_clock::now() #define MOTIS_STOP_TIMING(_X) auto _X##_stop = std::chrono::steady_clock::now() + +#define MOTIS_TIMING_S(_X) \ + (std::chrono::duration_cast>(_X##_stop - \ + _X##_start) \ + .count()) + #define MOTIS_TIMING_MS(_X) \ (std::chrono::duration_cast(_X##_stop - \ _X##_start) \ .count()) + #define MOTIS_TIMING_US(_X) \ (std::chrono::duration_cast(_X##_stop - \ _X##_start) \ .count()) +#define MOTIS_GET_TIMING_S(_X) \ + (std::chrono::duration_cast>( \ + std::chrono::steady_clock::now() - _X##_start) \ + .count()) + #define MOTIS_GET_TIMING_MS(_X) \ (std::chrono::duration_cast( \ std::chrono::steady_clock::now() - _X##_start) \ diff --git a/base/core/include/motis/core/otel/tracer.h b/base/core/include/motis/core/otel/tracer.h new file mode 100644 index 000000000..52b4b4832 --- /dev/null +++ b/base/core/include/motis/core/otel/tracer.h @@ -0,0 +1,11 @@ +#pragma once + +#include + +#include "opentelemetry/trace/tracer.h" + +namespace motis { + +extern std::shared_ptr motis_tracer; + +} // namespace motis diff --git a/base/core/src/otel/tracer.cc b/base/core/src/otel/tracer.cc new file mode 100644 index 000000000..11e1bf767 --- /dev/null +++ b/base/core/src/otel/tracer.cc @@ -0,0 +1,8 @@ +#include "motis/core/otel/tracer.h" + +namespace motis { + +// NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables) +std::shared_ptr motis_tracer; + +} // namespace motis diff --git a/base/launcher/include/motis/launcher/http_text_map_carrier.h b/base/launcher/include/motis/launcher/http_text_map_carrier.h new file mode 100644 index 000000000..36c0f2649 --- /dev/null +++ b/base/launcher/include/motis/launcher/http_text_map_carrier.h @@ -0,0 +1,34 @@ +#pragma once + +#include + +#include "boost/beast/http/fields.hpp" +#include "boost/beast/http/message.hpp" + +#include "opentelemetry/context/propagation/global_propagator.h" +#include "opentelemetry/context/propagation/text_map_propagator.h" +#include "opentelemetry/trace/propagation/http_trace_context.h" + +namespace motis::launcher { + +template +struct http_text_map_carrier + : public opentelemetry::context::propagation::TextMapCarrier { + explicit http_text_map_carrier(T& header) : header_{header} {} + + virtual opentelemetry::nostd::string_view Get( + opentelemetry::nostd::string_view key) const noexcept override { + return header_[key]; + } + + virtual void Set(opentelemetry::nostd::string_view key, + opentelemetry::nostd::string_view value) noexcept override { + if constexpr (!std::is_const_v) { + header_.set(key, value); + } + } + + T& header_; +}; + +} // namespace motis::launcher diff --git a/base/launcher/include/motis/launcher/launcher_settings.h b/base/launcher/include/motis/launcher/launcher_settings.h index 79a5fd167..289063f50 100644 --- a/base/launcher/include/motis/launcher/launcher_settings.h +++ b/base/launcher/include/motis/launcher/launcher_settings.h @@ -51,6 +51,7 @@ class launcher_settings : public conf::configuration { param(init_, "init", "init operation"); param(num_threads_, "num_threads", "number of worker threads"); param(direct_mode_, "direct", "no ctx/multi-threading"); + param(otlp_http_, "otlp_http", "enable OTLP HTTP exporter"); } motis_mode_t mode_{launcher_settings::motis_mode_t::SERVER}; @@ -59,6 +60,7 @@ class launcher_settings : public conf::configuration { std::string init_; unsigned num_threads_{std::thread::hardware_concurrency()}; bool direct_mode_{sizeof(void*) >= 8 ? false : true}; + bool otlp_http_{}; }; } // namespace motis::launcher diff --git a/base/launcher/include/motis/launcher/web_server.h b/base/launcher/include/motis/launcher/web_server.h index fd373f4d7..97a3f0810 100644 --- a/base/launcher/include/motis/launcher/web_server.h +++ b/base/launcher/include/motis/launcher/web_server.h @@ -5,12 +5,12 @@ #include "boost/asio/io_service.hpp" -#include "motis/module/receiver.h" +#include "motis/module/controller.h" namespace motis::launcher { struct web_server { - web_server(boost::asio::io_service&, motis::module::receiver&); + web_server(boost::asio::io_service&, motis::module::controller&); ~web_server(); web_server(web_server&&) = default; diff --git a/base/launcher/src/main.cc b/base/launcher/src/main.cc index 4c2d1e11e..8f6d78bfc 100644 --- a/base/launcher/src/main.cc +++ b/base/launcher/src/main.cc @@ -22,7 +22,21 @@ #include "google/protobuf/stubs/common.h" #endif +#include "opentelemetry/context/propagation/global_propagator.h" +#include "opentelemetry/context/propagation/text_map_propagator.h" +#include "opentelemetry/context/runtime_context.h" +#include "opentelemetry/exporters/otlp/otlp_http_exporter_factory.h" +#include "opentelemetry/sdk/trace/processor.h" +#include "opentelemetry/sdk/trace/recordable.h" +#include "opentelemetry/sdk/trace/simple_processor_factory.h" +#include "opentelemetry/sdk/trace/tracer_provider.h" +#include "opentelemetry/sdk/trace/tracer_provider_factory.h" +#include "opentelemetry/trace/propagation/http_trace_context.h" +#include "opentelemetry/trace/provider.h" +#include "opentelemetry/trace/tracer_provider.h" + #include "motis/core/common/logging.h" +#include "motis/core/otel/tracer.h" #include "motis/bootstrap/import_settings.h" #include "motis/bootstrap/module_settings.h" #include "motis/bootstrap/motis_instance.h" @@ -32,6 +46,8 @@ #include "motis/launcher/server_settings.h" #include "motis/launcher/web_server.h" +#include "motis/module/otel_runtime_context.h" + #include "version.h" using namespace motis::bootstrap; @@ -40,6 +56,48 @@ using namespace motis::module; using namespace motis::logging; using namespace motis; +namespace { + +void init_opentelemetry_tracer( + opentelemetry::sdk::resource::Resource const& resource) { + auto exporter = + opentelemetry::exporter::otlp::OtlpHttpExporterFactory::Create(); + + auto processor = + opentelemetry::sdk::trace::SimpleSpanProcessorFactory::Create( + std::move(exporter)); + + auto provider = + std::shared_ptr{opentelemetry::sdk::trace::TracerProviderFactory::Create( + std::move(processor), resource)}; + + opentelemetry::trace::Provider::SetTracerProvider(provider); +} + +void init_opentelemetry(launcher_settings const& launcher_opt) { + auto resource_attributes = opentelemetry::sdk::resource::ResourceAttributes{ + {"service.name", "motis"}, {"service.version", short_version()}}; + auto resource = + opentelemetry::sdk::resource::Resource::Create(resource_attributes); + + opentelemetry::context::RuntimeContext::SetRuntimeContextStorage( + std::make_shared()); + + if (launcher_opt.otlp_http_) { + init_opentelemetry_tracer(resource); + } + + opentelemetry::context::propagation::GlobalTextMapPropagator:: + SetGlobalPropagator( + std::make_shared< + opentelemetry::trace::propagation::HttpTraceContext>()); + + auto tracer_provider = opentelemetry::trace::Provider::GetTracerProvider(); + motis_tracer = tracer_provider->GetTracer("motis", short_version()); +} + +} // namespace + int main(int argc, char const** argv) { motis_instance instance; @@ -104,6 +162,8 @@ int main(int argc, char const** argv) { dispatcher::direct_mode_dispatcher_ = &instance; } + init_opentelemetry(launcher_opt); + try { instance.import(module_opt, import_opt); instance.init_modules(module_opt, launcher_opt.num_threads_); diff --git a/base/launcher/src/web_server.cc b/base/launcher/src/web_server.cc index ee11a5174..46d93256a 100644 --- a/base/launcher/src/web_server.cc +++ b/base/launcher/src/web_server.cc @@ -8,6 +8,15 @@ #include #include "boost/beast/version.hpp" +#include "boost/url/url_view.hpp" + +#include "fmt/format.h" + +#include "opentelemetry/context/propagation/global_propagator.h" +#include "opentelemetry/sdk/resource/semantic_conventions.h" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" +#include "opentelemetry/trace/tracer.h" #include "utl/helpers/algorithm.h" #include "utl/to_vec.h" @@ -18,7 +27,9 @@ #include "net/web_server/web_server.h" #include "motis/core/common/logging.h" +#include "motis/core/otel/tracer.h" #include "motis/module/client.h" +#include "motis/launcher/http_text_map_carrier.h" #include "motis/launcher/load_server_certificate.h" #if defined(NET_TLS) @@ -145,14 +156,14 @@ struct ws_client : public client, struct web_server::impl { #if defined(NET_TLS) - impl(boost::asio::io_service& ios, receiver& recvr) + impl(boost::asio::io_service& ios, controller& ctr) : ctx_{ssl::context::tlsv12}, ios_{ios}, - receiver_{recvr}, + receiver_{ctr}, server_{ios, ctx_} {} #else - impl(boost::asio::io_service& ios, receiver& recvr) - : ios_{ios}, receiver_{recvr}, server_{ios} {} + impl(boost::asio::io_service& ios, controller& ctr) + : ios_{ios}, receiver_{ctr}, server_{ios} {} #endif void listen(std::string const& host, std::string const& port, @@ -208,10 +219,36 @@ struct web_server::impl { void on_http_request(net::web_server::http_req_t const& req, net::web_server::http_res_cb_t const& cb) { using namespace boost::beast::http; + using namespace opentelemetry::sdk::resource; + + auto otel_propagator = opentelemetry::context::propagation:: + GlobalTextMapPropagator::GetGlobalPropagator(); + auto carrier = http_text_map_carrier{req}; + auto current_ctx = opentelemetry::context::RuntimeContext::GetCurrent(); + auto new_ctx = otel_propagator->Extract(carrier, current_ctx); + + auto const url = boost::urls::url_view{req.target()}; + + auto span = motis_tracer->StartSpan( + req.method_string(), + { + {SemanticConventions::kHttpRequestMethod, req.method_string()}, + {SemanticConventions::kUrlPath, url.path()}, + {SemanticConventions::kUrlQuery, url.query()}, + {SemanticConventions::kUrlScheme, "http"}, + }, + opentelemetry::trace::StartSpanOptions{ + .parent = opentelemetry::trace::GetSpan(new_ctx)->GetContext(), + .kind = opentelemetry::trace::SpanKind::kServer}); + auto scope = opentelemetry::trace::Scope{span}; + + if (auto const user_agent = req[field::user_agent]; !user_agent.empty()) { + span->SetAttribute(SemanticConventions::kUserAgentOriginal, user_agent); + } - auto const build_response = [req](msg_ptr const& response, - std::optional jf = - std::nullopt) { + auto const build_response = [req, span](msg_ptr const& response, + std::optional jf = + std::nullopt) { net::web_server::string_res_t res{ response == nullptr ? status::ok : response->get()->content_type() == MsgContent_MotisError @@ -226,6 +263,14 @@ struct web_server::impl { res.keep_alive(req.keep_alive()); res.set(field::server, BOOST_BEAST_VERSION_STRING); + span->SetAttribute(SemanticConventions::kHttpResponseStatusCode, + res.result_int()); + if (res.result() == status::internal_server_error) { + span->SetStatus(opentelemetry::trace::StatusCode::kError); + span->SetAttribute(SemanticConventions::kErrorType, + fmt::to_string(res.result_int())); + } + std::string content; auto has_already_content_encoding = false; if (response != nullptr && @@ -279,6 +324,9 @@ struct web_server::impl { return on_generic_req(req, res_cb); } req_msg = req.body(); + span->SetAttribute(SemanticConventions::kHttpRequestBodySize, + req_msg.size()); + span->SetAttribute("motis.http.request.body", req_msg); if (req_msg.empty()) { req_msg = make_no_msg(std::string{req.target()}) ->to_json(kDefaultOuputJsonFormat); @@ -289,6 +337,10 @@ struct web_server::impl { case verb::get: if (serve_static_files_ && net::serve_static_file(static_file_path_, req, cb)) { + span->UpdateName(fmt::format("{} /{{static}}", req.method_string())); + span->SetAttribute( + opentelemetry::sdk::resource::SemanticConventions::kHttpRoute, + "/{static}"); return; } else { req_msg = make_no_msg(std::string{req.target()}) @@ -300,7 +352,8 @@ struct web_server::impl { std::make_error_code(std::errc::operation_not_supported)))); } - return on_msg_req(req_msg, false, to_sv(req.target()), res_cb); + return on_msg_req(req_msg, false, to_sv(req.method_string()), + to_sv(req.target()), res_cb); } void on_ws_open(net::ws_session_ptr session, std::string const& target) { @@ -319,8 +372,16 @@ struct web_server::impl { void on_ws_msg(net::ws_session_ptr const& session, std::string const& msg, net::ws_msg_type type) { auto const is_binary = type == net::ws_msg_type::BINARY; + auto span = motis_tracer->StartSpan( + "WebSocket", + { + {"format", is_binary ? "binary" : "text"}, + }, + opentelemetry::trace::StartSpanOptions{ + .kind = opentelemetry::trace::SpanKind::kServer}); + auto scope = opentelemetry::trace::Scope{span}; return on_msg_req( - msg, is_binary, {}, + msg, is_binary, "WebSocket", {}, [session, type, is_binary](msg_ptr const& response, std::optional jf) { if (auto s = session.lock()) { @@ -332,7 +393,8 @@ struct web_server::impl { } void on_msg_req( - std::string const& request, bool binary, std::string_view const target, + std::string const& request, bool binary, std::string_view const method, + std::string_view const target, std::function)> const& cb, std::optional jf = std::nullopt) { msg_ptr err; @@ -342,8 +404,26 @@ struct web_server::impl { if (!jf) { jf = detected_jf; } + log_request(req); - req_id = req->get()->id(); + auto const* msg = req->get(); + req_id = msg->id(); + + auto span = motis_tracer->GetCurrentSpan(); + auto const op_name = + receiver_.get_operation_name(msg->destination()->target()->str()); + if (op_name) { + span->UpdateName(fmt::format("{} {}", method, *op_name)); + span->SetAttribute( + opentelemetry::sdk::resource::SemanticConventions::kHttpRoute, + *op_name); + } + span->SetAttribute("motis.message.id", req_id); + span->SetAttribute("motis.message.target", + msg->destination()->target()->view()); + span->SetAttribute("motis.message.type", + EnumNameMsgContent(msg->content_type())); + return receiver_.on_msg( req, ios_.wrap([cb, req_id, jf](msg_ptr const& res, std::error_code const& ec) { @@ -434,7 +514,7 @@ struct web_server::impl { ssl::context ctx_; #endif boost::asio::io_service& ios_; - receiver& receiver_; + controller& receiver_; net::web_server server_; bool logging_enabled_{false}; std::string log_path_; @@ -443,8 +523,8 @@ struct web_server::impl { bool serve_static_files_{false}; }; -web_server::web_server(boost::asio::io_service& ios, receiver& recvr) - : impl_(new impl(ios, recvr)) {} +web_server::web_server(boost::asio::io_service& ios, controller& ctr) + : impl_(new impl(ios, ctr)) {} web_server::~web_server() = default; diff --git a/base/module/CMakeLists.txt b/base/module/CMakeLists.txt index c8cb88ba9..7771be528 100644 --- a/base/module/CMakeLists.txt +++ b/base/module/CMakeLists.txt @@ -40,5 +40,6 @@ target_link_libraries(motis-module cista utl boost-url + opentelemetry_trace ) target_compile_options(motis-module PRIVATE ${MOTIS_CXX_FLAGS}) diff --git a/base/module/include/motis/module/ctx_data.h b/base/module/include/motis/module/ctx_data.h index ca0900429..af56df319 100644 --- a/base/module/include/motis/module/ctx_data.h +++ b/base/module/include/motis/module/ctx_data.h @@ -1,9 +1,13 @@ #pragma once +#include + #include "ctx/access_data.h" #include "ctx/access_scheduler.h" #include "ctx/operation.h" +#include "opentelemetry/context/context.h" + namespace motis::module { struct dispatcher; @@ -14,6 +18,7 @@ struct ctx_data : public ctx::access_data { void transition(ctx::transition, ctx::op_id const&, ctx::op_id const&) {} dispatcher* dispatcher_; + std::vector otel_context_stack_; }; inline ctx_data& current_data() { return ctx::current_op()->data_; } diff --git a/base/module/include/motis/module/global_res_ids.h b/base/module/include/motis/module/global_res_ids.h index 0df51e109..dd4ec3d90 100644 --- a/base/module/include/motis/module/global_res_ids.h +++ b/base/module/include/motis/module/global_res_ids.h @@ -18,6 +18,7 @@ enum class global_res_id { NIGIRI_TAGS, PPR_DATA, STATION_LOOKUP, + METRICS, FIRST_FREE_RES_ID }; diff --git a/base/module/include/motis/module/otel_runtime_context.h b/base/module/include/motis/module/otel_runtime_context.h new file mode 100644 index 000000000..9507766e1 --- /dev/null +++ b/base/module/include/motis/module/otel_runtime_context.h @@ -0,0 +1,70 @@ +#pragma once + +#include +#include + +#include "opentelemetry/context/context.h" +#include "opentelemetry/context/runtime_context.h" + +#include "ctx/operation.h" + +namespace motis::module { + +struct otel_runtime_context_storage + : public opentelemetry::context::RuntimeContextStorage { + opentelemetry::context::Context GetCurrent() noexcept override { + if (auto op = ctx::current_op(); op != nullptr) { + auto& stack = op->data_.otel_context_stack_; + return stack.empty() ? opentelemetry::context::Context{} : stack.back(); + } else { + return default_storage_->GetCurrent(); + } + } + + opentelemetry::nostd::unique_ptr Attach( + opentelemetry::context::Context const& context) noexcept override { + if (auto op = ctx::current_op(); op != nullptr) { + op->data_.otel_context_stack_.push_back(context); + return CreateToken(context); + } else { + return default_storage_->Attach(context); + } + } + + bool Detach(opentelemetry::context::Token& token) noexcept override { + if (auto op = ctx::current_op(); op != nullptr) { + auto& stack = op->data_.otel_context_stack_; + + if (stack.empty()) { + return false; + } + + if (token == stack.back()) { + stack.pop_back(); + return true; + } + + if (std::find_if(begin(stack), end(stack), [&token](auto const& context) { + return token == context; + }) == end(stack)) { + return false; + } + + while (!(token == stack.back())) { + stack.pop_back(); + } + + stack.pop_back(); + return true; + } else { + return default_storage_->Detach(token); + } + } + +private: + std::unique_ptr + default_storage_{std::make_unique< + opentelemetry::context::ThreadLocalContextStorage>()}; +}; + +} // namespace motis::module diff --git a/base/module/include/motis/module/registry.h b/base/module/include/motis/module/registry.h index c5d9bafa5..7fb6a51e5 100644 --- a/base/module/include/motis/module/registry.h +++ b/base/module/include/motis/module/registry.h @@ -3,6 +3,8 @@ #include #include #include +#include +#include #include "ctx/access_request.h" @@ -46,6 +48,8 @@ struct registry { std::optional get_operation(std::string const& prefix); + std::optional get_operation_name(std::string const& prefix); + void reset(); std::map operations_; diff --git a/base/module/src/context/motis_http_req.cc b/base/module/src/context/motis_http_req.cc index 25d303157..30c2f4b05 100644 --- a/base/module/src/context/motis_http_req.cc +++ b/base/module/src/context/motis_http_req.cc @@ -4,15 +4,22 @@ #include "boost/url/url.hpp" #include "boost/url/url_view.hpp" +#include "opentelemetry/context/runtime_context.h" +#include "opentelemetry/sdk/resource/semantic_conventions.h" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" + #include "net/http/client/http_client.h" #include "net/http/client/https_client.h" #include "motis/core/common/logging.h" +#include "motis/core/otel/tracer.h" #include "motis/module/context/get_io_service.h" using namespace motis::logging; using namespace net::http::client; +using namespace opentelemetry::sdk::resource; namespace motis::module { @@ -26,6 +33,31 @@ struct http_request_executor std::move(id))} {} void make_request(net::http::client::request req) { + auto const url = boost::urls::url_view{req.address.str()}; + auto port = url.port_number(); + if (port == 0) { + switch (url.scheme_id()) { + case boost::urls::scheme::http: port = 80; break; + case boost::urls::scheme::https: port = 443; break; + default: break; + } + } + + auto span_options = opentelemetry::trace::StartSpanOptions{}; + span_options.kind = opentelemetry::trace::SpanKind::kClient; + + span_ = motis_tracer->StartSpan( + "HTTP Request", + { + {SemanticConventions::kHttpRequestMethod, + net::http::client::method_to_str(req.req_method)}, + {SemanticConventions::kUrlFull, req.address.str()}, + {SemanticConventions::kServerAddress, req.address.host()}, + {SemanticConventions::kServerPort, port}, + }, + span_options); + auto scope = opentelemetry::trace::Scope{span_}; + l(debug, "http request {} {}", net::http::client::method_to_str(req.req_method), fmt::streamed(req.address)); @@ -44,6 +76,8 @@ struct http_request_executor make_http(ios_, req.peer())->query(req, std::move(cb)); } else { try { + span_->SetStatus(opentelemetry::trace::StatusCode::kError, + "unexpected port (not https or http)"); throw utl::fail("unexpected port {} (not https or http)", req.address.port()); } catch (...) { @@ -55,7 +89,14 @@ struct http_request_executor template void on_response(T, net::http::client::response&& res, boost::system::error_code ec) { + if (res.status_code != 0) { + span_->SetAttribute(SemanticConventions::kHttpResponseStatusCode, + res.status_code); + } if (ec.failed()) { + span_->AddEvent("exception", {{"exception.message", ec.what()}}); + span_->SetStatus(opentelemetry::trace::StatusCode::kError, + "system error exception"); try { throw std::system_error{ec}; } catch (...) { @@ -64,6 +105,7 @@ struct http_request_executor } else { if (auto const it = res.headers.find("location"); it != end(res.headers)) { + span_->AddEvent("redirect", {{"location", it->second}}); redirect(it->second); } else { f_->set(std::move(res)); @@ -91,6 +133,7 @@ struct http_request_executor boost::asio::io_service& ios_; http_future_t f_; url request_url_; + std::shared_ptr span_; }; std::shared_ptr> diff --git a/base/module/src/dispatcher.cc b/base/module/src/dispatcher.cc index 3e6ab578e..82e6b91e7 100644 --- a/base/module/src/dispatcher.cc +++ b/base/module/src/dispatcher.cc @@ -6,11 +6,19 @@ #include "boost/asio/post.hpp" #include "boost/system/system_error.hpp" +#include "fmt/format.h" + +#include "opentelemetry/context/runtime_context.h" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" +#include "opentelemetry/trace/tracer.h" + #include "ctx/ctx.h" #include "utl/to_vec.h" #include "motis/core/common/logging.h" +#include "motis/core/otel/tracer.h" #include "motis/module/error.h" #include "motis/module/global_res_ids.h" #include "motis/module/module.h" @@ -105,11 +113,24 @@ future dispatcher::req(msg_ptr const& msg, ctx_data const& data, void dispatcher::dispatch(msg_ptr const& msg, callback const& cb, ctx::op_id id, ctx::op_type_t const op_type, ctx_data const* data) { id.name = msg->get()->destination()->target()->str(); + + auto op_name = registry_.get_operation_name(id.name); + if (id.name == "/api") { + op_name = id.name; + } + auto span = motis_tracer->StartSpan( + op_name.value_or(std::string_view{"unknown target"}), + {{"ctx.op_id.name", id.name}, + {"ctx.op_id.index", id.index}, + {"ctx.op_id.created_at", id.created_at}, + {"ctx.op_id.parent_index", id.parent_index}}); + auto scope = opentelemetry::trace::Scope{span}; + if (id.name == "/api") { return cb(api_desc(msg->id()), std::error_code{}); } - auto const run = [this, id, cb, msg]() { + auto const run = [this, id, cb, msg, span]() { try { if (auto const op = registry_.get_operation(id.name)) { return cb(op->fn_(msg), std::error_code()); @@ -120,14 +141,30 @@ void dispatcher::dispatch(msg_ptr const& msg, callback const& cb, ctx::op_id id, return; } else { LOG(logging::warn) << "target not found: " << id.name; + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "target not found"); return handle_no_target(msg, cb); } } catch (std::system_error const& e) { + span->AddEvent("exception", + {{"exception.message", e.what()}, + {"exception.error.code", e.code().value()}, + {"exception.error.category", e.code().category().name()}, + {"exception.error.message", e.code().message()}}); + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "system error exception"); return cb(nullptr, e.code()); } catch (std::exception const& e) { + span->AddEvent("exception", { + {"exception.message", e.what()}, + }); + span->SetStatus(opentelemetry::trace::StatusCode::kError, "exception"); LOG(logging::error) << "error executing " << id.name << ": " << e.what(); return cb(nullptr, error::unknown_error); } catch (...) { + span->AddEvent("exception", {{"exception.type", "unknown"}}); + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "unknown error"); LOG(logging::error) << "unknown error executing " << id.name; return cb(nullptr, error::unknown_error); } @@ -141,9 +178,12 @@ void dispatcher::dispatch(msg_ptr const& msg, callback const& cb, ctx::op_id id, access = op->access_; } + auto new_data = data != nullptr ? ctx_data{*data} : ctx_data{this}; + new_data.otel_context_stack_.push_back( + opentelemetry::context::RuntimeContext::GetCurrent()); enqueue( - data != nullptr ? ctx_data{*data} : ctx_data{this}, [run]() { run(); }, - id, op_type, std::move(access)); + std::move(new_data), [run]() { run(); }, id, op_type, + std::move(access)); } } diff --git a/base/module/src/event_collector.cc b/base/module/src/event_collector.cc index e048f2245..d46d6c5e6 100644 --- a/base/module/src/event_collector.cc +++ b/base/module/src/event_collector.cc @@ -2,9 +2,14 @@ #include +#include "fmt/format.h" #include "fmt/ranges.h" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" + #include "motis/core/common/logging.h" +#include "motis/core/otel/tracer.h" #include "motis/module/clog_redirect.h" #include "motis/module/context/motis_publish.h" @@ -66,6 +71,8 @@ event_collector* event_collector::require( } // All messages arrived -> start. + auto span = motis_tracer->StartSpan(fmt::format("import {}", module_name_)); + auto scope = opentelemetry::trace::Scope{span}; activate_progress_tracker(progress_tracker_); progress_tracker_->status("RUNNING").show_progress(true); try { @@ -75,9 +82,13 @@ event_collector* event_collector::require( } catch (std::exception const& e) { progress_tracker_->status(fmt::format("ERROR: {}", e.what())) .show_progress(false); + span->AddEvent("exception", {{"exception.message", e.what()}}); + span->SetStatus(opentelemetry::trace::StatusCode::kError, "exception"); } catch (...) { progress_tracker_->status("ERROR: UNKNOWN EXCEPTION") .show_progress(false); + span->AddEvent("exception"); + span->SetStatus(opentelemetry::trace::StatusCode::kError, "exception"); } return nullptr; diff --git a/base/module/src/registry.cc b/base/module/src/registry.cc index ea961ca05..6fc86483b 100644 --- a/base/module/src/registry.cc +++ b/base/module/src/registry.cc @@ -88,6 +88,24 @@ std::optional registry::get_operation(std::string const& prefix) { } } +std::optional registry::get_operation_name( + std::string const& prefix) { + if (auto const it = operations_.upper_bound(prefix); + it != begin(operations_) && + boost::algorithm::starts_with(prefix, std::next(it, -1)->first)) { + return std::string_view{std::next(it, -1)->first}; + } else { + std::lock_guard const g{remote_op_mutex_}; + if (auto const it = remote_operations_.upper_bound(prefix); + it != begin(remote_operations_) && + boost::algorithm::starts_with(prefix, std::next(it, -1)->first)) { + return std::string_view{std::next(it, -1)->first}; + } else { + return std::nullopt; + } + } +} + void registry::reset() { operations_.clear(); topic_subscriptions_.clear(); diff --git a/base/module/src/timer.cc b/base/module/src/timer.cc index fe06385c0..e214a620f 100644 --- a/base/module/src/timer.cc +++ b/base/module/src/timer.cc @@ -1,6 +1,12 @@ #include "motis/module/timer.h" +#include "opentelemetry/context/runtime_context.h" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" +#include "opentelemetry/trace/tracer.h" + #include "motis/core/common/logging.h" +#include "motis/core/otel/tracer.h" #include "motis/module/ctx_data.h" #include "motis/module/dispatcher.h" @@ -40,16 +46,31 @@ void timer::exec(boost::system::error_code const& ec) { return; } + auto span = + motis_tracer->StartSpan(name_, {{"timer.interval", interval_.seconds()}}); + auto scope = opentelemetry::trace::Scope{span}; + auto access_copy = access_; + auto data = ctx_data{dispatcher_}; + data.otel_context_stack_.push_back( + opentelemetry::context::RuntimeContext::GetCurrent()); dispatcher_->enqueue( - ctx_data{dispatcher_}, - [self = shared_from_this()]() { + std::move(data), + [self = shared_from_this(), span]() { try { self->fn_(); } catch (std::exception const& e) { + span->AddEvent("exception", { + {"exception.message", e.what()}, + }); + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "exception"); LOG(logging::error) << "error in timer " << self->name_ << ": " << e.what(); } catch (...) { + span->AddEvent("exception", {{"exception.type", "unknown"}}); + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "unknown error"); LOG(logging::error) << "unknown error in timer " << self->name_; } }, diff --git a/modules/adr/src/adr.cc b/modules/adr/src/adr.cc index fe411560f..6d480032e 100644 --- a/modules/adr/src/adr.cc +++ b/modules/adr/src/adr.cc @@ -9,6 +9,9 @@ #include "boost/thread/tss.hpp" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" + #include "cista/reflection/comparable.h" #include "utl/to_vec.h" @@ -18,6 +21,7 @@ #include "motis/core/common/logging.h" #include "motis/core/conv/position_conv.h" +#include "motis/core/otel/tracer.h" #include "motis/module/event_collector.h" #include "motis/module/ini_io.h" @@ -61,15 +65,24 @@ void adr::import(motis::module::import_dispatcher& reg) { mm::event_collector::publish_fn_t const&) { using import::OSMEvent; + auto span = motis_tracer->StartSpan("adr::import"); + auto scope = opentelemetry::trace::Scope{span}; + auto const dir = get_data_directory() / "adr"; auto const osm = motis_content(OSMEvent, dependencies.at("OSM")); auto const state = import_state{data_path(osm->path()->str()), osm->hash(), osm->size()}; + span->SetAttribute("motis.osm.file", osm->path()->str()); + span->SetAttribute("motis.osm.size", osm->size()); + if (mm::read_ini(dir / "import.ini") != state) { + span->SetAttribute("motis.import.state", "changed"); fs::create_directories(dir); a::extract(osm->path()->str(), (dir / "adr"), dir); mm::write_ini(dir / "import.ini", state); + } else { + span->SetAttribute("motis.import.state", "unchanged"); } impl_ = std::make_unique(a::read(dir / "adr.t.adr", false)); diff --git a/modules/intermodal/include/motis/intermodal/intermodal.h b/modules/intermodal/include/motis/intermodal/intermodal.h index 28737fedd..418a2d096 100644 --- a/modules/intermodal/include/motis/intermodal/intermodal.h +++ b/modules/intermodal/include/motis/intermodal/intermodal.h @@ -1,5 +1,6 @@ #pragma once +#include #include #include "motis/module/module.h" @@ -7,6 +8,8 @@ namespace motis::intermodal { +struct metrics; + struct intermodal : public motis::module::module { public: intermodal(); @@ -28,6 +31,7 @@ struct intermodal : public motis::module::module { bool revise_{false}; unsigned timeout_{0}; ppr_profiles ppr_profiles_; + std::unique_ptr metrics_; }; } // namespace motis::intermodal diff --git a/modules/intermodal/include/motis/intermodal/metrics.h b/modules/intermodal/include/motis/intermodal/metrics.h new file mode 100644 index 000000000..d5719d603 --- /dev/null +++ b/modules/intermodal/include/motis/intermodal/metrics.h @@ -0,0 +1,26 @@ +#pragma once + +#include "prometheus/counter.h" +#include "prometheus/histogram.h" +#include "prometheus/registry.h" + +namespace motis::intermodal { + +struct metrics { + prometheus::Registry& registry_; + + prometheus::Counter& fwd_requests_; + prometheus::Counter& bwd_requests_; + + prometheus::Counter& foot_modes_; + prometheus::Counter& foot_ppr_modes_; + prometheus::Counter& bike_modes_; + prometheus::Counter& car_modes_; + prometheus::Counter& car_parking_modes_; + prometheus::Counter& gbfs_modes_; + + prometheus::Histogram& mumo_edges_time_; + prometheus::Histogram& total_time_; +}; + +} // namespace motis::intermodal diff --git a/modules/intermodal/include/motis/intermodal/mumo_edge.h b/modules/intermodal/include/motis/intermodal/mumo_edge.h index 904117e8b..68b12b52c 100644 --- a/modules/intermodal/include/motis/intermodal/mumo_edge.h +++ b/modules/intermodal/include/motis/intermodal/mumo_edge.h @@ -85,12 +85,14 @@ using appender_fun = std::function; +struct metrics; + void make_starts(IntermodalRoutingRequest const*, geo::latlng const& pos, geo::latlng const& direct_target, appender_fun const&, - mumo_stats_appender_fun const&, ppr_profiles const&); + mumo_stats_appender_fun const&, ppr_profiles const&, metrics&); void make_dests(IntermodalRoutingRequest const*, geo::latlng const& pos, geo::latlng const& direct_target, appender_fun const&, - mumo_stats_appender_fun const&, ppr_profiles const&); + mumo_stats_appender_fun const&, ppr_profiles const&, metrics&); void remove_intersection(std::vector& starts, std::vector& destinations, diff --git a/modules/intermodal/src/intermodal.cc b/modules/intermodal/src/intermodal.cc index f7058b6e9..a777bb1bd 100644 --- a/modules/intermodal/src/intermodal.cc +++ b/modules/intermodal/src/intermodal.cc @@ -9,17 +9,28 @@ #include "utl/to_vec.h" #include "utl/verify.h" +#include "prometheus/family.h" +#include "prometheus/gauge.h" +#include "prometheus/histogram.h" +#include "prometheus/registry.h" + +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" +#include "opentelemetry/trace/tracer.h" + #include "motis/core/common/constants.h" #include "motis/core/common/timing.h" #include "motis/core/access/time_access.h" #include "motis/core/journey/journeys_to_message.h" #include "motis/core/journey/message_to_journeys.h" +#include "motis/core/otel/tracer.h" #include "motis/module/context/motis_call.h" #include "motis/module/context/motis_spawn.h" #include "motis/intermodal/direct_connections.h" #include "motis/intermodal/error.h" #include "motis/intermodal/eval/commands.h" +#include "motis/intermodal/metrics.h" #include "motis/intermodal/mumo_edge.h" #include "motis/intermodal/query_bounds.h" #include "motis/intermodal/statistics.h" @@ -48,6 +59,48 @@ void intermodal::reg_subc(motis::module::subc_reg& r) { } void intermodal::init(motis::module::registry& r) { + auto prometheus_registry = + get_shared_data>( + to_res_id(global_res_id::METRICS)); + + auto& request_counter_family = + prometheus::BuildCounter() + .Name("intermodal_requests_total") + .Help("Number of intermodal routing requests") + .Register(*prometheus_registry); + + auto& mode_counter_family = prometheus::BuildCounter() + .Name("intermodal_modes_total") + .Help("Number of intermodal routing requests") + .Register(*prometheus_registry); + + auto const time_buckets = prometheus::Histogram::BucketBoundaries{ + .05, .1, .25, .5, .75, 1.0, 2.0, 3.0, 4.0, 5.0, + 6.0, 7.0, 8.0, 9.0, 10.0, 20.0, 30.0, 45.0, 60.0}; + + metrics_ = std::make_unique(metrics{ + .registry_ = *prometheus_registry, + .fwd_requests_ = request_counter_family.Add({{"direction", "forward"}}), + .bwd_requests_ = request_counter_family.Add({{"direction", "backward"}}), + .foot_modes_ = mode_counter_family.Add({{"mode", "foot"}}), + .foot_ppr_modes_ = mode_counter_family.Add({{"mode", "foot_ppr"}}), + .bike_modes_ = mode_counter_family.Add({{"mode", "bike"}}), + .car_modes_ = mode_counter_family.Add({{"mode", "car"}}), + .car_parking_modes_ = mode_counter_family.Add({{"mode", "car_parking"}}), + .gbfs_modes_ = mode_counter_family.Add({{"mode", "gbfs"}}), + .mumo_edges_time_ = + prometheus::BuildHistogram() + .Name("intermodal_mumo_edges_time_seconds") + .Help("Total time to calculate mumo edges per routing request") + .Register(*prometheus_registry) + .Add({}, time_buckets), + .total_time_ = prometheus::BuildHistogram() + .Name("intermodal_total_time_seconds") + .Help("Total time per intermodal routing request") + .Register(*prometheus_registry) + .Add({}, time_buckets), + }); + r.register_op("/intermodal", [this](msg_ptr const& m) { return route(m); }, {}); if (router_.empty()) { @@ -441,6 +494,11 @@ msg_ptr intermodal::route(msg_ptr const& msg) { message_creator mc; statistics stats{}; + auto span = motis_tracer->StartSpan("intermodal::route"); + auto scope = opentelemetry::trace::Scope{span}; + + MOTIS_START_TIMING(total_timing); + auto const start = parse_query_start(mc, req); auto const dest = parse_query_dest(mc, req); @@ -470,13 +528,14 @@ msg_ptr intermodal::route(msg_ptr const& msg) { using namespace std::placeholders; if (req->search_dir() == SearchDir_Forward) { + metrics_->fwd_requests_.Increment(); if (start.is_intermodal_) { futures.emplace_back(spawn_job_void([&]() { make_starts( req, start.pos_, dest.pos_, std::bind(appender, std::ref(deps), // NOLINT STATION_START, _1, start.pos_, _2, _3, _4, _5, _6), - mumo_stats_appender, ppr_profiles_); + mumo_stats_appender, ppr_profiles_, *metrics_); })); } if (dest.is_intermodal_) { @@ -484,17 +543,18 @@ msg_ptr intermodal::route(msg_ptr const& msg) { make_dests(req, dest.pos_, start.pos_, std::bind(appender, std::ref(arrs), // NOLINT _1, STATION_END, _2, dest.pos_, _3, _4, _5, _6), - mumo_stats_appender, ppr_profiles_); + mumo_stats_appender, ppr_profiles_, *metrics_); })); } } else { + metrics_->bwd_requests_.Increment(); if (start.is_intermodal_) { futures.emplace_back(spawn_job_void([&]() { make_starts( req, start.pos_, dest.pos_, std::bind(appender, std::ref(deps), // NOLINT _1, STATION_START, _2, start.pos_, _3, _4, _5, _6), - mumo_stats_appender, ppr_profiles_); + mumo_stats_appender, ppr_profiles_, *metrics_); })); } if (dest.is_intermodal_) { @@ -502,13 +562,14 @@ msg_ptr intermodal::route(msg_ptr const& msg) { make_dests(req, dest.pos_, start.pos_, std::bind(appender, std::ref(arrs), // NOLINT STATION_END, _1, dest.pos_, _2, _3, _4, _5, _6), - mumo_stats_appender, ppr_profiles_); + mumo_stats_appender, ppr_profiles_, *metrics_); })); } } ctx::await_all(futures); MOTIS_STOP_TIMING(mumo_edge_timing); + metrics_->mumo_edges_time_.Observe(MOTIS_TIMING_S(mumo_edge_timing)); stats.start_edges_ = deps.size(); stats.destination_edges_ = arrs.size(); @@ -561,8 +622,14 @@ msg_ptr intermodal::route(msg_ptr const& msg) { static_cast(MOTIS_TIMING_MS(routing_timing)); } - return postprocess_response(routing_resp, start, dest, req, edge_mapping, - stats, revise_, mumo_stats, ppr_profiles_); + auto const response = + postprocess_response(routing_resp, start, dest, req, edge_mapping, stats, + revise_, mumo_stats, ppr_profiles_); + + MOTIS_STOP_TIMING(total_timing); + metrics_->total_time_.Observe(MOTIS_TIMING_S(total_timing)); + + return response; } } // namespace motis::intermodal diff --git a/modules/intermodal/src/mumo_edge.cc b/modules/intermodal/src/mumo_edge.cc index 2a695a486..0bb476845 100644 --- a/modules/intermodal/src/mumo_edge.cc +++ b/modules/intermodal/src/mumo_edge.cc @@ -10,6 +10,7 @@ #include "motis/module/message.h" #include "motis/intermodal/error.h" +#include "motis/intermodal/metrics.h" using namespace geo; using namespace flatbuffers; @@ -259,13 +260,14 @@ void make_edges(Vector> const* modes, latlng const& pos, appender_fun const& appender, mumo_stats_appender_fun const& mumo_stats_appender, std::string const& mumo_stats_prefix, - ppr_profiles const& profiles) { + ppr_profiles const& profiles, metrics& metrics) { for (auto const& wrapper : *modes) { switch (wrapper->mode_type()) { case Mode_Foot: { auto const max_dur = reinterpret_cast(wrapper->mode())->max_duration(); auto const max_dist = max_dur * WALK_SPEED; + metrics.foot_modes_.Increment(); osrm_edges(pos, max_dur, max_dist, mumo_type::FOOT, search_dir, appender); break; @@ -275,6 +277,7 @@ void make_edges(Vector> const* modes, latlng const& pos, auto const max_dur = reinterpret_cast(wrapper->mode())->max_duration(); auto const max_dist = max_dur * BIKE_SPEED; + metrics.bike_modes_.Increment(); osrm_edges(pos, max_dur, max_dist, mumo_type::BIKE, search_dir, appender); break; @@ -284,6 +287,7 @@ void make_edges(Vector> const* modes, latlng const& pos, auto const max_dur = reinterpret_cast(wrapper->mode())->max_duration(); auto const max_dist = max_dur * CAR_SPEED; + metrics.car_modes_.Increment(); osrm_edges(pos, max_dur, max_dist, mumo_type::CAR, search_dir, appender); break; @@ -292,12 +296,14 @@ void make_edges(Vector> const* modes, latlng const& pos, case Mode_FootPPR: { auto const options = reinterpret_cast(wrapper->mode())->search_options(); + metrics.foot_ppr_modes_.Increment(); ppr_edges(pos, options, search_dir, appender, profiles); break; } case Mode_CarParking: { auto const cp = reinterpret_cast(wrapper->mode()); + metrics.car_parking_modes_.Increment(); car_parking_edges(pos, cp->max_car_duration(), cp->ppr_search_options(), search_dir, appender, mumo_stats_appender, mumo_stats_prefix); @@ -306,6 +312,7 @@ void make_edges(Vector> const* modes, latlng const& pos, case Mode_GBFS: { auto const gbfs = reinterpret_cast(wrapper->mode()); + metrics.gbfs_modes_.Increment(); gbfs_edges(appender, search_dir, pos, direct_target, gbfs->provider()->str(), gbfs->max_walk_duration() / 60.0, gbfs->max_vehicle_duration() / 60.0); @@ -320,17 +327,19 @@ void make_edges(Vector> const* modes, latlng const& pos, void make_starts(IntermodalRoutingRequest const* req, latlng const& pos, latlng const& direct_target, appender_fun const& appender, mumo_stats_appender_fun const& mumo_stats_appender, - ppr_profiles const& profiles) { + ppr_profiles const& profiles, metrics& metrics) { make_edges(req->start_modes(), pos, direct_target, SearchDir_Forward, - appender, mumo_stats_appender, "intermodal.start.", profiles); + appender, mumo_stats_appender, "intermodal.start.", profiles, + metrics); } void make_dests(IntermodalRoutingRequest const* req, latlng const& pos, latlng const& direct_target, appender_fun const& appender, mumo_stats_appender_fun const& mumo_stats_appender, - ppr_profiles const& profiles) { + ppr_profiles const& profiles, metrics& metrics) { make_edges(req->destination_modes(), pos, direct_target, SearchDir_Backward, - appender, mumo_stats_appender, "intermodal.dest.", profiles); + appender, mumo_stats_appender, "intermodal.dest.", profiles, + metrics); } void remove_intersection(std::vector& starts, diff --git a/modules/metrics/CMakeLists.txt b/modules/metrics/CMakeLists.txt new file mode 100644 index 000000000..a97451443 --- /dev/null +++ b/modules/metrics/CMakeLists.txt @@ -0,0 +1,16 @@ +cmake_minimum_required(VERSION 3.10) +project(motis) + +include_directories(include) + +file(GLOB_RECURSE motis-metrics-files src/*.cc) +add_library(motis-metrics STATIC ${motis-metrics-files}) +target_include_directories(motis-metrics PUBLIC include) +target_compile_features(motis-metrics PRIVATE cxx_std_23) +target_link_libraries(motis-metrics + boost-system + boost-thread + motis-module + prometheus-cpp::core +) +target_compile_options(motis-metrics PRIVATE ${MOTIS_CXX_FLAGS}) diff --git a/modules/metrics/include/motis/metrics/metrics.h b/modules/metrics/include/motis/metrics/metrics.h new file mode 100644 index 000000000..c54d75570 --- /dev/null +++ b/modules/metrics/include/motis/metrics/metrics.h @@ -0,0 +1,24 @@ +#pragma once + +#include + +#include "motis/module/module.h" + +namespace motis::metrics { + +struct metrics : public motis::module::module { + metrics(); + ~metrics() noexcept override; + + metrics(metrics const&) = delete; + metrics& operator=(metrics const&) = delete; + + metrics(metrics&&) = delete; + metrics& operator=(metrics&&) = delete; + + void init(motis::module::registry&) override; + + motis::module::msg_ptr request(motis::module::msg_ptr const&) const; +}; + +} // namespace motis::metrics diff --git a/modules/metrics/src/metrics.cc b/modules/metrics/src/metrics.cc new file mode 100644 index 000000000..265347a4b --- /dev/null +++ b/modules/metrics/src/metrics.cc @@ -0,0 +1,45 @@ +#include "motis/metrics/metrics.h" + +#include "prometheus/registry.h" +#include "prometheus/text_serializer.h" + +namespace mm = motis::module; +namespace fbs = flatbuffers; + +namespace motis::metrics { + +metrics::metrics() : module("Metrics", "metrics") {} + +metrics::~metrics() noexcept = default; + +void metrics::init(mm::registry& reg) { + reg.register_op("/metrics", + [&](mm::msg_ptr const& msg) { return request(msg); }, {}); +} + +mm::msg_ptr metrics::request(mm::msg_ptr const&) const { + auto registry = get_shared_data>( + to_res_id(mm::global_res_id::METRICS)) + .get(); + + auto const serializer = prometheus::TextSerializer{}; + auto const metrics_str = serializer.Serialize(registry->Collect()); + + mm::message_creator mc; + + auto headers = std::vector>{}; + headers.emplace_back( + CreateHTTPHeader(mc, mc.CreateString("Content-Type"), + mc.CreateString("text/plain; version=0.0.4"))); + + auto payload = mc.CreateString(metrics_str); + + mc.create_and_finish( + MsgContent_HTTPResponse, + CreateHTTPResponse(mc, HTTPStatus_OK, mc.CreateVector(headers), payload) + .Union()); + + return make_msg(mc); +} + +} // namespace motis::metrics diff --git a/modules/nigiri/CMakeLists.txt b/modules/nigiri/CMakeLists.txt index a0ba5ea2c..e1dc14200 100644 --- a/modules/nigiri/CMakeLists.txt +++ b/modules/nigiri/CMakeLists.txt @@ -7,5 +7,5 @@ file(GLOB_RECURSE motis-nigiri-files src/*.cc) add_library(motis-nigiri STATIC ${motis-nigiri-files}) target_include_directories(motis-nigiri PUBLIC include) target_compile_features(motis-nigiri PRIVATE cxx_std_20) -target_link_libraries(motis-nigiri boost-system boost-thread boost-filesystem motis-module nigiri tiles guess) +target_link_libraries(motis-nigiri boost-system boost-thread boost-filesystem motis-module nigiri tiles guess prometheus-cpp::core) target_compile_options(motis-nigiri PRIVATE ${MOTIS_CXX_FLAGS}) diff --git a/modules/nigiri/include/motis/nigiri/gtfsrt.h b/modules/nigiri/include/motis/nigiri/gtfsrt.h index 9d2f945b6..7137c7d99 100644 --- a/modules/nigiri/include/motis/nigiri/gtfsrt.h +++ b/modules/nigiri/include/motis/nigiri/gtfsrt.h @@ -2,17 +2,46 @@ #include #include +#include + +#include "prometheus/counter.h" #include "motis/module/context/motis_http_req.h" #include "motis/nigiri/tag_lookup.h" +namespace nigiri::rt { +struct statistics; +} + namespace motis::nigiri { +struct metrics; + +struct gtfsrt_metrics { + prometheus::Counter& updates_requested_; + prometheus::Counter& updates_successful_; + prometheus::Counter& updates_error_; + + prometheus::Counter& total_entities_; + prometheus::Counter& total_entities_success_; + prometheus::Counter& total_entities_fail_; + prometheus::Counter& unsupported_deleted_; + prometheus::Counter& unsupported_vehicle_; + prometheus::Counter& unsupported_alert_; + prometheus::Counter& unsupported_no_trip_id_; + prometheus::Counter& no_trip_update_; + prometheus::Counter& trip_update_without_trip_; + prometheus::Counter& trip_resolve_error_; + prometheus::Counter& unsupported_schedule_relationship_; + prometheus::Gauge& feed_timestamp_; + prometheus::Gauge& last_update_timestamp_; +}; + struct gtfsrt { // Config format: tag|url|auth // Example 1: nl|http://gtfs.ovapi.nl/nl/tripUpdates.pb|my_api_key // Example 2: nl|http://gtfs.ovapi.nl/nl/tripUpdates.pb - gtfsrt(tag_lookup const&, std::string_view config); + gtfsrt(tag_lookup const&, std::string_view config, metrics&); gtfsrt(gtfsrt&&) noexcept; gtfsrt& operator=(gtfsrt&&) noexcept; ~gtfsrt(); @@ -20,8 +49,14 @@ struct gtfsrt { motis::module::http_future_t fetch() const; ::nigiri::source_idx_t src() const; + void update_metrics(::nigiri::rt::statistics const&) const; + struct impl; std::unique_ptr impl_; + + std::string tag_; + std::string url_; + std::unique_ptr metrics_; }; -} // namespace motis::nigiri \ No newline at end of file +} // namespace motis::nigiri diff --git a/modules/nigiri/include/motis/nigiri/metrics.h b/modules/nigiri/include/motis/nigiri/metrics.h new file mode 100644 index 000000000..b92320307 --- /dev/null +++ b/modules/nigiri/include/motis/nigiri/metrics.h @@ -0,0 +1,50 @@ +#pragma once + +#include "prometheus/counter.h" +#include "prometheus/family.h" +#include "prometheus/gauge.h" +#include "prometheus/histogram.h" +#include "prometheus/registry.h" + +namespace motis::nigiri { + +struct metrics { + explicit metrics(prometheus::Registry& registry); + + prometheus::Registry& registry_; + + prometheus::Family& request_counter_family_; + prometheus::Counter& pretrip_requests_; + prometheus::Counter& ontrip_station_requests_; + + prometheus::Histogram& via_count_; + + prometheus::Family& routing_time_family_; + prometheus::Histogram& pretrip_routing_time_; + prometheus::Histogram& ontrip_station_routing_time_; + + prometheus::Histogram& pretrip_interval_extensions_; + + prometheus::Histogram& reconstruction_errors_; + + prometheus::Family& gtfsrt_updates_requested_; + prometheus::Family& gtfsrt_updates_successful_; + prometheus::Family& gtfsrt_updates_error_; + + prometheus::Family& gtfsrt_total_entities_; + prometheus::Family& gtfsrt_total_entities_success_; + prometheus::Family& gtfsrt_total_entities_fail_; + prometheus::Family& gtfsrt_unsupported_deleted_; + prometheus::Family& gtfsrt_unsupported_vehicle_; + prometheus::Family& gtfsrt_unsupported_alert_; + prometheus::Family& gtfsrt_unsupported_no_trip_id_; + prometheus::Family& gtfsrt_no_trip_update_; + prometheus::Family& gtfsrt_trip_update_without_trip_; + prometheus::Family& gtfsrt_trip_resolve_error_; + prometheus::Family& + gtfsrt_unsupported_schedule_relationship_; + prometheus::Family& gtfsrt_feed_timestamp_; + prometheus::Family& gtfsrt_last_update_timestamp_; +}; + +} // namespace motis::nigiri diff --git a/modules/nigiri/include/motis/nigiri/routing.h b/modules/nigiri/include/motis/nigiri/routing.h index ce6630aaf..0bd78b9c2 100644 --- a/modules/nigiri/include/motis/nigiri/routing.h +++ b/modules/nigiri/include/motis/nigiri/routing.h @@ -12,10 +12,11 @@ struct rt_timetable; namespace motis::nigiri { struct tag_lookup; +struct metrics; motis::module::msg_ptr route( tag_lookup const&, ::nigiri::timetable const&, - ::nigiri::rt_timetable const*, motis::module::msg_ptr const&, + ::nigiri::rt_timetable const*, motis::module::msg_ptr const&, metrics&, ::nigiri::profile_idx_t const prf_idx = ::nigiri::profile_idx_t{0U}); -} // namespace motis::nigiri \ No newline at end of file +} // namespace motis::nigiri diff --git a/modules/nigiri/src/gtfsrt.cc b/modules/nigiri/src/gtfsrt.cc index b1a83f177..84b8909e8 100644 --- a/modules/nigiri/src/gtfsrt.cc +++ b/modules/nigiri/src/gtfsrt.cc @@ -4,7 +4,12 @@ #include "net/http/client/request.h" +#include "prometheus/registry.h" + +#include "nigiri/rt/gtfsrt_update.h" + #include "motis/nigiri/location.h" +#include "motis/nigiri/metrics.h" namespace mm = motis::module; namespace n = nigiri; @@ -18,9 +23,12 @@ struct gtfsrt::impl { n::source_idx_t src_; }; -gtfsrt::gtfsrt(tag_lookup const& tags, std::string_view config) { +gtfsrt::gtfsrt(tag_lookup const& tags, std::string_view config, + metrics& metrics) { auto const [tag, url, auth] = utl::split<'|', utl::cstr, utl::cstr, utl::cstr>(config); + tag_ = tag.to_str(); + url_ = url.to_str(); auto const src = tags.get_src(tag.to_str() + "_"); utl::verify( src != n::source_idx_t::invalid(), @@ -33,6 +41,41 @@ gtfsrt::gtfsrt(tag_lookup const& tags, std::string_view config) { : req.headers.emplace("Authorization", auth.to_str()); } impl_ = std::make_unique(std::move(req), src); + metrics_ = std::make_unique(gtfsrt_metrics{ + .updates_requested_ = + metrics.gtfsrt_updates_requested_.Add({{"tag", tag.to_str()}}), + .updates_successful_ = + metrics.gtfsrt_updates_successful_.Add({{"tag", tag.to_str()}}), + .updates_error_ = + metrics.gtfsrt_updates_error_.Add({{"tag", tag.to_str()}}), + .total_entities_ = + metrics.gtfsrt_total_entities_.Add({{"tag", tag.to_str()}}), + .total_entities_success_ = + metrics.gtfsrt_total_entities_success_.Add({{"tag", tag.to_str()}}), + .total_entities_fail_ = + metrics.gtfsrt_total_entities_fail_.Add({{"tag", tag.to_str()}}), + .unsupported_deleted_ = + metrics.gtfsrt_unsupported_deleted_.Add({{"tag", tag.to_str()}}), + .unsupported_vehicle_ = + metrics.gtfsrt_unsupported_vehicle_.Add({{"tag", tag.to_str()}}), + .unsupported_alert_ = + metrics.gtfsrt_unsupported_alert_.Add({{"tag", tag.to_str()}}), + .unsupported_no_trip_id_ = + metrics.gtfsrt_unsupported_no_trip_id_.Add({{"tag", tag.to_str()}}), + .no_trip_update_ = + metrics.gtfsrt_no_trip_update_.Add({{"tag", tag.to_str()}}), + .trip_update_without_trip_ = + metrics.gtfsrt_trip_update_without_trip_.Add({{"tag", tag.to_str()}}), + .trip_resolve_error_ = + metrics.gtfsrt_trip_resolve_error_.Add({{"tag", tag.to_str()}}), + .unsupported_schedule_relationship_ = + metrics.gtfsrt_unsupported_schedule_relationship_.Add( + {{"tag", tag.to_str()}}), + .feed_timestamp_ = + metrics.gtfsrt_feed_timestamp_.Add({{"tag", tag.to_str()}}), + .last_update_timestamp_ = + metrics.gtfsrt_last_update_timestamp_.Add({{"tag", tag.to_str()}}), + }); } gtfsrt::gtfsrt(gtfsrt&&) noexcept = default; @@ -44,4 +87,22 @@ mm::http_future_t gtfsrt::fetch() const { return motis_http(impl_->req_); } n::source_idx_t gtfsrt::src() const { return impl_->src_; } -} // namespace motis::nigiri \ No newline at end of file +void gtfsrt::update_metrics(::nigiri::rt::statistics const& stats) const { + metrics_->total_entities_.Increment(stats.total_entities_); + metrics_->total_entities_success_.Increment(stats.total_entities_success_); + metrics_->total_entities_fail_.Increment(stats.total_entities_fail_); + metrics_->unsupported_deleted_.Increment(stats.unsupported_deleted_); + metrics_->unsupported_vehicle_.Increment(stats.unsupported_vehicle_); + metrics_->unsupported_alert_.Increment(stats.unsupported_alert_); + metrics_->unsupported_no_trip_id_.Increment(stats.unsupported_no_trip_id_); + metrics_->no_trip_update_.Increment(stats.no_trip_update_); + metrics_->trip_update_without_trip_.Increment( + stats.trip_update_without_trip_); + metrics_->trip_resolve_error_.Increment(stats.trip_resolve_error_); + metrics_->unsupported_schedule_relationship_.Increment( + stats.unsupported_schedule_relationship_); + metrics_->feed_timestamp_.Set( + static_cast(stats.feed_timestamp_.time_since_epoch().count())); +} + +} // namespace motis::nigiri diff --git a/modules/nigiri/src/metrics.cc b/modules/nigiri/src/metrics.cc new file mode 100644 index 000000000..a1c14b480 --- /dev/null +++ b/modules/nigiri/src/metrics.cc @@ -0,0 +1,137 @@ +#include "motis/nigiri/metrics.h" + +namespace motis::nigiri { + +auto const routing_time_buckets = prometheus::Histogram::BucketBoundaries{ + .05, .1, .25, .5, .75, 1.0, 2.0, 3.0, 4.0, 5.0, + 6.0, 7.0, 8.0, 9.0, 10.0, 20.0, 30.0, 45.0, 60.0}; + +metrics::metrics(prometheus::Registry& registry) + : registry_{registry}, + request_counter_family_{prometheus::BuildCounter() + .Name("nigiri_routing_requests_total") + .Help("Number of routing requests") + .Register(registry)}, + pretrip_requests_{request_counter_family_.Add({{"type", "pretrip"}})}, + ontrip_station_requests_{ + request_counter_family_.Add({{"type", "ontrip_station"}})}, + via_count_{ + prometheus::BuildHistogram() + .Name("nigiri_via_count") + .Help("Number of via stops per routing request") + .Register(registry) + .Add({}, prometheus::Histogram::BucketBoundaries{0, 1, 2})}, + routing_time_family_{prometheus::BuildHistogram() + .Name("nigiri_routing_time_seconds") + .Help("Total time per routing request") + .Register(registry)}, + pretrip_routing_time_{routing_time_family_.Add({{"type", "pretrip"}}, + routing_time_buckets)}, + ontrip_station_routing_time_{routing_time_family_.Add( + {{"type", "ontrip_station"}}, routing_time_buckets)}, + pretrip_interval_extensions_{ + prometheus::BuildHistogram() + .Name("nigiri_interval_extensions") + .Help("Number of interval extensions per routing request") + .Register(registry) + .Add({{"type", "pretrip"}}, + prometheus::Histogram::BucketBoundaries{0, 1, 2, 3, 4, 5, 6, + 7, 8, 9, 10})}, + reconstruction_errors_{ + prometheus::BuildHistogram() + .Name("nigiri_reconstruction_errors") + .Help("Number of journey reconstruction errors per routing " + "request") + .Register(registry) + .Add({}, + prometheus::Histogram::BucketBoundaries{0, 1, 2, 3, 4, 5, 6, + 7, 8, 9, 10})}, + gtfsrt_updates_requested_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_updates_requested_total") + .Help("Number of update attempts of the GTFS-RT feed") + .Register(registry)}, + gtfsrt_updates_successful_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_updates_successful_total") + .Help("Number of successful updates of the GTFS-RT feed") + .Register(registry)}, + gtfsrt_updates_error_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_updates_error_total") + .Help("Number of failed updates of the GTFS-RT feed") + .Register(registry)}, + gtfsrt_total_entities_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_total_entities_total") + .Help("Total number of entities in the GTFS-RT feed") + .Register(registry)}, + gtfsrt_total_entities_success_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_total_entities_success_total") + .Help("Number of entities in the GTFS-RT feed that were " + "successfully processed") + .Register(registry)}, + gtfsrt_total_entities_fail_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_total_entities_fail_total") + .Help("Number of entities in the GTFS-RT feed that could not " + "be processed") + .Register(registry)}, + gtfsrt_unsupported_deleted_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_unsupported_deleted_total") + .Help("Number of unsupported deleted entities in the GTFS-RT " + "feed") + .Register(registry)}, + gtfsrt_unsupported_vehicle_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_unsupported_vehicle_total") + .Help("Number of unsupported vehicle entities in the GTFS-RT " + "feed") + .Register(registry)}, + gtfsrt_unsupported_alert_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_unsupported_alert_total") + .Help("Number of unsupported alert entities in the GTFS-RT feed") + .Register(registry)}, + gtfsrt_unsupported_no_trip_id_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_unsupported_no_trip_id_total") + .Help("Number of unsupported trips without trip id in the " + "GTFS-RT feed") + .Register(registry)}, + gtfsrt_no_trip_update_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_no_trip_update_total") + .Help("Number of unsupported trips without trip update in the " + "GTFS-RT feed") + .Register(registry)}, + gtfsrt_trip_update_without_trip_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_trip_update_without_trip_total") + .Help("Number of unsupported trip updates without trip in the " + "GTFS-RT feed") + .Register(registry)}, + gtfsrt_trip_resolve_error_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_trip_resolve_error_total") + .Help("Number of unresolved trips in the GTFS-RT feed") + .Register(registry)}, + gtfsrt_unsupported_schedule_relationship_{ + prometheus::BuildCounter() + .Name("nigiri_gtfsrt_unsupported_schedule_relationship_total") + .Help("Number of unsupported schedule relationships in the " + "GTFS-RT feed") + .Register(registry)}, + gtfsrt_feed_timestamp_{prometheus::BuildGauge() + .Name("nigiri_gtfsrt_feed_timestamp_seconds") + .Help("Timestamp of the GTFS-RT feed") + .Register(registry)}, + gtfsrt_last_update_timestamp_{ + prometheus::BuildGauge() + .Name("nigiri_gtfsrt_last_update_timestamp_seconds") + .Help("Last update timestamp of the GTFS-RT feed") + .Register(registry)} {} + +} // namespace motis::nigiri diff --git a/modules/nigiri/src/nigiri.cc b/modules/nigiri/src/nigiri.cc index 4568eacfe..142d4b59d 100644 --- a/modules/nigiri/src/nigiri.cc +++ b/modules/nigiri/src/nigiri.cc @@ -1,6 +1,7 @@ #include "motis/nigiri/nigiri.h" #include +#include #include #include "boost/filesystem.hpp" @@ -11,6 +12,11 @@ #include "conf/date_time.h" +#include "prometheus/registry.h" + +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" + #include "utl/enumerate.h" #include "utl/helpers/algorithm.h" #include "utl/verify.h" @@ -28,12 +34,15 @@ #include "nigiri/timetable.h" #include "motis/core/common/logging.h" +#include "motis/core/otel/tracer.h" #include "motis/module/event_collector.h" +#include "motis/module/global_res_ids.h" #include "motis/nigiri/geo_station_lookup.h" #include "motis/nigiri/get_station.h" #include "motis/nigiri/gtfsrt.h" #include "motis/nigiri/guesser.h" #include "motis/nigiri/initial_permalink.h" +#include "motis/nigiri/metrics.h" #include "motis/nigiri/railviz.h" #include "motis/nigiri/routing.h" #include "motis/nigiri/station_lookup.h" @@ -73,7 +82,7 @@ struct schedule_info { }; struct nigiri::impl { - impl() { + explicit impl(std::shared_ptr prometheus_registry) { loaders_.emplace_back(std::make_unique()); loaders_.emplace_back( std::make_unique()); @@ -83,6 +92,8 @@ struct nigiri::impl { std::make_unique()); loaders_.emplace_back( std::make_unique()); + + metrics_ = std::make_unique(*prometheus_registry); } void update_rtt(std::shared_ptr rtt) { @@ -123,6 +134,7 @@ struct nigiri::impl { std::string initial_permalink_; std::vector schedules_{}; cista::hash_t hash_{0U}; + std::unique_ptr metrics_{}; }; nigiri::nigiri() : module("Next Generation Routing", "nigiri") { @@ -163,16 +175,30 @@ nigiri::nigiri() : module("Next Generation Routing", "nigiri") { nigiri::~nigiri() = default; void nigiri::init(motis::module::registry& reg) { + auto span = motis_tracer->StartSpan("nigiri::init"); + auto scope = opentelemetry::trace::Scope{span}; if (!gtfsrt_paths_.empty()) { auto const rtt_copy = std::make_shared(*impl_->get_rtt()); auto statistics = std::vector{}; for (auto const& p : gtfsrt_paths_) { auto const [tag, path] = utl::split<'|', utl::cstr, utl::cstr>(p); if (path.empty()) { + span->AddEvent( + "config error", + {{"message", "bad GTFS-RT path (required: tag|path/to/file)"}, + {"path", p}}); + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "config error"); throw utl::fail("bad GTFS-RT path: {} (required: tag|path/to/file)", p); } auto const src = impl_->tags_.get_src(tag.to_str() + '_'); if (src == n::source_idx_t::invalid()) { + span->AddEvent("config error", + {{"message", "bad GTFS-RT path: tag not found"}, + {"path", p}, + {"tag", tag.view()}}); + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "config error"); throw utl::fail("bad GTFS-RT path: tag {} not found", tag.view()); } auto const file = @@ -185,10 +211,18 @@ void nigiri::init(motis::module::registry& reg) { stats.parser_error_ = true; LOG(logging::error) << "GTFS-RT update error (tag=" << tag.view() << ") " << e.what(); + span->AddEvent("exception", {{"exception.message", e.what()}, + {"tag", tag.view()}, + {"path", path.view()}, + {"during", "GTFS-RT update"}}); } catch (...) { stats.parser_error_ = true; LOG(logging::error) << "Unknown GTFS-RT update error (tag= " << tag.view() << ")"; + span->AddEvent("exception", {{"exception.type", "unknown"}, + {"tag", tag.view()}, + {"path", path.view()}, + {"during", "GTFS-RT update"}}); } statistics.emplace_back(stats); } @@ -201,13 +235,17 @@ void nigiri::init(motis::module::registry& reg) { << static_cast(stats.total_entities_success_) / stats.total_entities_ * 100 << "%)"; + span->AddEvent("GTFS-RT init", + {{"path", path}, + {"total_entities_success", stats.total_entities_success_}, + {"total_entities", stats.total_entities_}}); } } reg.register_op("/nigiri", [&](mm::msg_ptr const& msg) { return route(impl_->tags_, **impl_->tt_, - impl_->get_rtt().get(), msg); + impl_->get_rtt().get(), msg, *impl_->metrics_); }, {}); @@ -216,7 +254,8 @@ void nigiri::init(motis::module::registry& reg) { reg.register_op(fmt::format("/nigiri/{}", prf_name), [&, p = prf_idx, this](mm::msg_ptr const& msg) { return route(impl_->tags_, **impl_->tt_, - impl_->get_rtt().get(), msg, p); + impl_->get_rtt().get(), msg, + *impl_->metrics_, p); }, {}); } @@ -304,7 +343,7 @@ void nigiri::init(motis::module::registry& reg) { void nigiri::register_gtfsrt_timer(mm::dispatcher& d) { if (!gtfsrt_urls_.empty()) { impl_->gtfsrt_ = utl::to_vec(gtfsrt_urls_, [&](auto&& config) { - return gtfsrt{impl_->tags_, config}; + return gtfsrt{impl_->tags_, config, *impl_->metrics_}; }); d.register_timer("RIS GTFS-RT Update", boost::posix_time::seconds{gtfsrt_update_interval_sec_}, @@ -316,8 +355,15 @@ void nigiri::register_gtfsrt_timer(mm::dispatcher& d) { void nigiri::update_gtfsrt() { LOG(logging::info) << "Starting GTFS-RT update: fetch URLs"; - auto const futures = utl::to_vec( - impl_->gtfsrt_, [](auto& endpoint) { return endpoint.fetch(); }); + auto outer_span = motis_tracer->StartSpan("nigiri::update_gtfsrt"); + auto outer_scope = opentelemetry::trace::Scope{outer_span}; + + auto const futures = utl::to_vec(impl_->gtfsrt_, [](auto& endpoint) { + auto span = motis_tracer->StartSpan( + "fetch", {{"tag", endpoint.tag_}, {"url", endpoint.url_}}); + auto scope = opentelemetry::trace::Scope{span}; + return endpoint.fetch(); + }); auto const today = std::chrono::time_point_cast( std::chrono::system_clock::now()); auto const rtt = gtfsrt_incremental_ @@ -327,25 +373,68 @@ void nigiri::update_gtfsrt() { n::rt::create_rt_timetable(**impl_->tt_, today)); auto statistics = std::vector{}; for (auto const [f, endpoint] : utl::zip(futures, impl_->gtfsrt_)) { + auto span = motis_tracer->StartSpan( + "process", {{"tag", endpoint.tag_}, {"url", endpoint.url_}}); + auto scope = opentelemetry::trace::Scope{span}; + auto const tag = impl_->tags_.get_tag_clean(endpoint.src()); auto stats = n::rt::statistics{}; + endpoint.metrics_->updates_requested_.Increment(); try { auto const& body = f->val().body; + span->AddEvent("received", {{"http.response.length", body.size()}}); if (debug_) { std::ofstream{fmt::format("{}/{}.json", get_data_directory(), tag)} << n::rt::protobuf_to_json(body); } stats = n::rt::gtfsrt_update_buf(**impl_->tt_, *rtt, endpoint.src(), tag, body); + endpoint.metrics_->updates_successful_.Increment(); + endpoint.metrics_->last_update_timestamp_.SetToCurrentTime(); + span->SetAttribute("motis.gtfsrt.feed.timestamp", + static_cast( + stats.feed_timestamp_.time_since_epoch().count())); + span->SetAttribute("motis.gtfsrt.feed.total_entities", + stats.total_entities_); + span->SetAttribute("motis.gtfsrt.feed.total_entities_success", + stats.total_entities_success_); + span->SetAttribute("motis.gtfsrt.feed.total_entities_fail", + stats.total_entities_fail_); + span->SetAttribute("motis.gtfsrt.feed.unsupported_deleted", + stats.unsupported_deleted_); + span->SetAttribute("motis.gtfsrt.feed.unsupported_vehicle", + stats.unsupported_vehicle_); + span->SetAttribute("motis.gtfsrt.feed.unsupported_alert", + stats.unsupported_alert_); + span->SetAttribute("motis.gtfsrt.feed.unsupported_no_trip_id", + stats.unsupported_no_trip_id_); + span->SetAttribute("motis.gtfsrt.feed.no_trip_update", + stats.no_trip_update_); + span->SetAttribute("motis.gtfsrt.feed.trip_update_without_trip", + stats.trip_update_without_trip_); + span->SetAttribute("motis.gtfsrt.feed.trip_resolve_error", + stats.trip_resolve_error_); + span->SetAttribute("motis.gtfsrt.feed.unsupported_schedule_relationship", + stats.unsupported_schedule_relationship_); } catch (std::exception const& e) { stats.parser_error_ = true; + span->AddEvent("exception", { + {"exception.message", e.what()}, + }); + span->SetStatus(opentelemetry::trace::StatusCode::kError, "exception"); LOG(logging::error) << "GTFS-RT update error (tag=" << tag << ") " << e.what(); + endpoint.metrics_->updates_error_.Increment(); } catch (...) { stats.parser_error_ = true; + span->AddEvent("exception", {{"exception.type", "unknown"}}); + span->SetStatus(opentelemetry::trace::StatusCode::kError, + "unknown error"); LOG(logging::error) << "Unknown GTFS-RT update error (tag= " << tag << ")"; + endpoint.metrics_->updates_error_.Increment(); } + endpoint.update_metrics(stats); statistics.emplace_back(stats); } impl_->update_rtt(rtt); @@ -358,13 +447,18 @@ void nigiri::update_gtfsrt() { } void nigiri::import(motis::module::import_dispatcher& reg) { - impl_ = std::make_unique(); + impl_ = std::make_unique( + get_shared_data>( + to_res_id(mm::global_res_id::METRICS))); std::make_shared( get_data_directory().generic_string(), "nigiri", reg, [this](mm::event_collector::dependencies_map_t const& dependencies, mm::event_collector::publish_fn_t const& publish) { using import::FileEvent; + auto span = motis_tracer->StartSpan("nigiri::import"); + auto scope = opentelemetry::trace::Scope{span}; + auto const& msg = dependencies.at("SCHEDULE"); utl::verify( @@ -391,6 +485,11 @@ void nigiri::import(motis::module::import_dispatcher& reg) { LOG(logging::info) << "interval: " << interval.from_ << " - " << interval.to_; + span->SetAttribute("motis.nigiri.import.interval.from", + date::format("%F", interval.from_)); + span->SetAttribute("motis.nigiri.import.interval.to", + date::format("%F", interval.to_)); + auto h = cista::hash_combine(cista::BASE_HASH, interval.from_.time_since_epoch().count(), // @@ -409,6 +508,10 @@ void nigiri::import(motis::module::import_dispatcher& reg) { continue; } auto const path = fs::path{p->path()->str()}; + + span->AddEvent("add dataset", {{"tag", p->options()->str()}, + {"path", path.string()}}); + auto d = n::loader::make_dir(path); auto const c = utl::find_if( impl_->loaders_, [&](auto&& c) { return c->applicable(*d); }); @@ -428,10 +531,16 @@ void nigiri::import(motis::module::import_dispatcher& reg) { auto const data_dir = get_data_directory() / "nigiri"; auto const dump_file_path = data_dir / fmt::to_string(h); + span->SetAttribute("motis.nigiri.import.dump_file", + dump_file_path.string()); + auto loaded = false; for (auto i = 0U; i != 2; ++i) { // Parse from input files and write memory image. if (no_cache_ || !fs::is_regular_file(dump_file_path)) { + auto parse_span = motis_tracer->StartSpan("parse timetable"); + auto parse_scope = opentelemetry::trace::Scope{parse_span}; + impl_->tt_ = std::make_shared>( cista::raw::make_unique()); @@ -441,8 +550,14 @@ void nigiri::import(motis::module::import_dispatcher& reg) { auto traffic_day_bitfields = n::hash_map{}; for (auto const& [src, loader, dir] : datasets) { - auto progress_tracker = utl::activate_progress_tracker( - fmt::format("{}nigiri", impl_->tags_.get_tag(src))); + auto const tag = impl_->tags_.get_tag(src); + auto progress_tracker = + utl::activate_progress_tracker(fmt::format("{}nigiri", tag)); + + auto inner_span = motis_tracer->StartSpan( + "load timetable", + {{"tag", tag}, {"loader", (*loader)->name()}}); + auto inner_scope = opentelemetry::trace::Scope{inner_span}; LOG(logging::info) << "loading nigiri timetable with configuration " @@ -455,25 +570,39 @@ void nigiri::import(motis::module::import_dispatcher& reg) { nullptr, nullptr); progress_tracker->status("FINISHED").show_progress(false); } catch (std::exception const& e) { + inner_span->AddEvent("exception", + {{"exception.message", e.what()}}); + inner_span->SetStatus(opentelemetry::trace::StatusCode::kError, + "exception"); progress_tracker->status(fmt::format("ERROR: {}", e.what())) .show_progress(false); throw; } catch (...) { + inner_span->AddEvent("exception"); + inner_span->SetStatus(opentelemetry::trace::StatusCode::kError, + "exception"); progress_tracker->status("ERROR: UNKNOWN EXCEPTION") .show_progress(false); throw; } } - n::loader::finalize(**impl_->tt_, adjust_footpaths_, - merge_dupes_intra_src_, merge_dupes_inter_src_, - max_footpath_length_); + { + auto const fin_span = motis_tracer->StartSpan("finalize"); + auto const fin_scope = opentelemetry::trace::Scope{fin_span}; + n::loader::finalize(**impl_->tt_, adjust_footpaths_, + merge_dupes_intra_src_, + merge_dupes_inter_src_, max_footpath_length_); + } if (no_cache_) { loaded = true; break; } else { // Write to disk, next step: read from disk. + auto const write_span = + motis_tracer->StartSpan("write cached timetable image"); + auto const write_scope = opentelemetry::trace::Scope{write_span}; std::filesystem::create_directories(data_dir); (*impl_->tt_)->write(dump_file_path); } @@ -482,6 +611,9 @@ void nigiri::import(motis::module::import_dispatcher& reg) { // Read memory image from disk. impl_->hash_ = h; if (!no_cache_) { + auto const read_span = + motis_tracer->StartSpan("read cached timetable image"); + auto const read_scope = opentelemetry::trace::Scope{read_span}; try { impl_->tt_ = std::make_shared>( n::timetable::read(cista::memory_holder{ @@ -497,6 +629,10 @@ void nigiri::import(motis::module::import_dispatcher& reg) { } catch (std::exception const& e) { LOG(logging::error) << "cannot read cached timetable image: " << e.what(); + read_span->SetStatus(opentelemetry::trace::StatusCode::kError, + "exception"); + read_span->AddEvent("exception", + {{"exception.message", e.what()}}); std::filesystem::remove(dump_file_path); continue; } @@ -511,6 +647,8 @@ void nigiri::import(motis::module::import_dispatcher& reg) { << "\n"; if (lookup_) { + auto lookup_scope = opentelemetry::trace::Scope{ + motis_tracer->StartSpan("init lookup")}; impl_->station_lookup_ = std::make_shared( impl_->tags_, **impl_->tt_); auto copy = impl_->station_lookup_; @@ -519,11 +657,15 @@ void nigiri::import(motis::module::import_dispatcher& reg) { } if (guesser_) { + auto lookup_scope = opentelemetry::trace::Scope{ + motis_tracer->StartSpan("init guesser")}; impl_->guesser_ = std::make_unique(impl_->tags_, (**impl_->tt_)); } if (railviz_) { + auto lookup_scope = opentelemetry::trace::Scope{ + motis_tracer->StartSpan("init railviz")}; impl_->initial_permalink_ = get_initial_permalink(**impl_->tt_); impl_->railviz_ = std::make_unique(impl_->tags_, (**impl_->tt_)); diff --git a/modules/nigiri/src/routing.cc b/modules/nigiri/src/routing.cc index 1aaa6503b..e49f5653f 100644 --- a/modules/nigiri/src/routing.cc +++ b/modules/nigiri/src/routing.cc @@ -2,6 +2,9 @@ #include "boost/thread/tss.hpp" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" + #include "utl/erase_if.h" #include "utl/helpers/algorithm.h" #include "utl/pipes.h" @@ -18,7 +21,9 @@ #include "motis/core/common/timing.h" #include "motis/core/access/error.h" #include "motis/core/journey/journeys_to_message.h" +#include "motis/core/otel/tracer.h" #include "motis/nigiri/location.h" +#include "motis/nigiri/metrics.h" #include "motis/nigiri/nigiri_to_motis_journey.h" #include "motis/nigiri/unixtime_conv.h" @@ -149,10 +154,13 @@ n::routing::clasz_mask_t to_clasz_mask(fbs::Vector const* v) { motis::module::msg_ptr route(tag_lookup const& tags, n::timetable const& tt, n::rt_timetable const* rtt, motis::module::msg_ptr const& msg, - n::profile_idx_t const prf_idx) { + metrics& metrics, n::profile_idx_t const prf_idx) { using motis::routing::RoutingRequest; auto const req = motis_content(RoutingRequest, msg); + auto span = motis_tracer->StartSpan("nigiri::route"); + auto scope = opentelemetry::trace::Scope{span}; + auto min_connection_count = static_cast(0U); auto extend_interval_earlier = false; auto extend_interval_later = false; @@ -167,6 +175,7 @@ motis::module::msg_ptr route(tag_lookup const& tags, n::timetable const& tt, }(); if (req->start_type() == routing::Start_PretripStart) { + metrics.pretrip_requests_.Increment(); auto const start = reinterpret_cast(req->start()); start_time = n::interval{ @@ -177,6 +186,7 @@ motis::module::msg_ptr route(tag_lookup const& tags, n::timetable const& tt, extend_interval_earlier = start->extend_interval_earlier(); extend_interval_later = start->extend_interval_later(); } else if (req->start_type() == routing::Start_OntripStationStart) { + metrics.ontrip_station_requests_.Increment(); auto const start = reinterpret_cast(req->start()); start_time = to_nigiri_unixtime(start->departure_time()); @@ -186,6 +196,7 @@ motis::module::msg_ptr route(tag_lookup const& tags, n::timetable const& tt, } else { throw utl::fail("OntripTrainStart not supported"); } + metrics.via_count_.Observe(req->via()->size()); auto const destination_station = get_location_idx(tags, tt, req->destination()->id()->str()); @@ -352,6 +363,28 @@ motis::module::msg_ptr route(tag_lookup const& tags, n::timetable const& tt, search_interval = r.interval_; MOTIS_STOP_TIMING(routing); + auto const reconstruction_errors = static_cast(utl::count_if( + *r.journeys_, [](n::routing::journey const& j) { return j.error_; })); + metrics.reconstruction_errors_.Observe(reconstruction_errors); + + if (req->start_type() == routing::Start_PretripStart) { + metrics.pretrip_routing_time_.Observe(MOTIS_TIMING_S(routing)); + metrics.pretrip_interval_extensions_.Observe( + static_cast(search_stats.interval_extensions_)); + } else if (req->start_type() == routing::Start_OntripStationStart) { + metrics.ontrip_station_routing_time_.Observe(MOTIS_TIMING_S(routing)); + } + + span->AddEvent("routing done", + {{"journeys", r.journeys_->size()}, + {"reconstruction_errors", reconstruction_errors}}); + + span->SetAttribute("motis.nigiri.result.journeys", + static_cast(r.journeys_->size())); + + span->SetAttribute("motis.nigiri.result.reconstruction_errors", + reconstruction_errors); + return to_routing_response(tt, rtt, tags, journeys, search_interval, search_stats, raptor_stats, MOTIS_TIMING_MS(routing)); diff --git a/modules/nigiri/test/dst_test.cc b/modules/nigiri/test/dst_test.cc index b9eb77310..47902733c 100644 --- a/modules/nigiri/test/dst_test.cc +++ b/modules/nigiri/test/dst_test.cc @@ -12,6 +12,7 @@ #include "motis/core/conv/trip_conv.h" #include "motis/core/journey/extern_trip.h" +#include "motis/nigiri/metrics.h" #include "motis/nigiri/resolve_run.h" #include "motis/nigiri/routing.h" #include "motis/nigiri/tag_lookup.h" @@ -75,11 +76,14 @@ TEST(nigiri, dst_test) { auto tags = mn::tag_lookup{}; tags.add(n::source_idx_t{0U}, "swiss_"); + auto prometheus_registry = prometheus::Registry{}; + auto metrics = mn::metrics{prometheus_registry}; auto const routing_response = mn::route( tags, tt, nullptr, mn::make_routing_msg( "swiss_8101236", "swiss_8503000:0:9", - mn::to_unix(date::sys_days{2023_y / October / 29} + 14h + 48min))); + mn::to_unix(date::sys_days{2023_y / October / 29} + 14h + 48min)), + metrics); using namespace motis; using motis::routing::RoutingResponse; diff --git a/modules/nigiri/test/max_transfers_test.cc b/modules/nigiri/test/max_transfers_test.cc index 1cdffc8e9..7e2006393 100644 --- a/modules/nigiri/test/max_transfers_test.cc +++ b/modules/nigiri/test/max_transfers_test.cc @@ -9,6 +9,7 @@ #include "motis/core/journey/journey.h" #include "motis/core/journey/message_to_journeys.h" #include "motis/core/journey/print_journey.h" +#include "motis/nigiri/metrics.h" #include "motis/nigiri/routing.h" #include "motis/nigiri/tag_lookup.h" @@ -209,12 +210,16 @@ TEST(nigiri, max_transfers_test) { auto tags = mn::tag_lookup{}; tags.add(n::source_idx_t{0U}, "tag_"); + auto prometheus_registry = prometheus::Registry{}; + auto metrics = mn::metrics{prometheus_registry}; + { // Default transfer limit -> should find all 3 connections auto const results = mn::route( tags, tt, nullptr, mn::make_routing_msg( "tag_A", "tag_D", - mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min))); + mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min)), + metrics); auto const journeys = message_to_journeys(motis_content(RoutingResponse, results)); @@ -231,7 +236,8 @@ TEST(nigiri, max_transfers_test) { tags, tt, nullptr, mn::make_routing_msg( "tag_A", "tag_D", - mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min), 1)); + mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min), 1), + metrics); auto const journeys = message_to_journeys(motis_content(RoutingResponse, results)); @@ -248,7 +254,8 @@ TEST(nigiri, max_transfers_test) { tags, tt, nullptr, mn::make_routing_msg( "tag_A", "tag_D", - mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min), 0)); + mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min), 0), + metrics); auto const journeys = message_to_journeys(motis_content(RoutingResponse, results)); diff --git a/modules/nigiri/test/rt_test.cc b/modules/nigiri/test/rt_test.cc index 6e7dc17b2..364e320d7 100644 --- a/modules/nigiri/test/rt_test.cc +++ b/modules/nigiri/test/rt_test.cc @@ -11,6 +11,7 @@ #include "motis/core/journey/journey.h" #include "motis/core/journey/message_to_journeys.h" #include "motis/core/journey/print_journey.h" +#include "motis/nigiri/metrics.h" #include "motis/nigiri/routing.h" #include "motis/nigiri/tag_lookup.h" @@ -168,12 +169,16 @@ TEST(nigiri, rt_test) { auto tags = mn::tag_lookup{}; tags.add(n::source_idx_t{0U}, "tag_"); + auto prometheus_registry = prometheus::Registry{}; + auto metrics = mn::metrics{prometheus_registry}; + /*** BASE LINE: A@09:00 -> E@09:55 direct via T1 ***/ - auto const r0 = mn::route( - tags, tt, &rtt, - mn::make_routing_msg( - "tag_A", "tag_E", - mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min))); + auto const r0 = + mn::route(tags, tt, &rtt, + mn::make_routing_msg( + "tag_A", "tag_E", + mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min)), + metrics); auto const j0 = message_to_journeys(motis_content(RoutingResponse, r0)); ASSERT_EQ(1U, j0.size()); EXPECT_EQ(0U, j0[0].transfers_); @@ -186,11 +191,12 @@ TEST(nigiri, rt_test) { .stop_updates_ = {{.stop_id_ = "E", .skip_ = true}}}}, date::sys_days{2019_y / May / 1} + 9h)); EXPECT_EQ(1U, stats0.total_entities_success_); - auto const r1 = mn::route( - tags, tt, &rtt, - mn::make_routing_msg( - "tag_A", "tag_E", - mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min))); + auto const r1 = + mn::route(tags, tt, &rtt, + mn::make_routing_msg( + "tag_A", "tag_E", + mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min)), + metrics); auto const j1 = message_to_journeys(motis_content(RoutingResponse, r1)); ASSERT_EQ(1U, j1.size()); EXPECT_EQ(0U, j1[0].transfers_); @@ -238,7 +244,8 @@ TEST(nigiri, rt_test) { auto const routing_response = mn::route( tags, tt, &rtt, mn::make_routing_msg("tag_A", "tag_E", - mn::to_unix(date::sys_days{2019_y / May / 1} + 8h))); + mn::to_unix(date::sys_days{2019_y / May / 1} + 8h)), + metrics); auto const journeys = message_to_journeys(motis_content(RoutingResponse, routing_response)); @@ -255,11 +262,12 @@ TEST(nigiri, rt_test) { mn::to_feed_msg({{.trip_id_ = "TX", .cancelled_ = false}}, date::sys_days{2019_y / May / 1} + 9h)); EXPECT_EQ(1U, stats2.total_entities_success_); - auto const r2 = mn::route( - tags, tt, &rtt, - mn::make_routing_msg( - "tag_A", "tag_E", - mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min))); + auto const r2 = + mn::route(tags, tt, &rtt, + mn::make_routing_msg( + "tag_A", "tag_E", + mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min)), + metrics); auto const j2 = message_to_journeys(motis_content(RoutingResponse, r2)); ASSERT_EQ(1U, j2.size()); EXPECT_EQ(0U, j2[0].transfers_); @@ -275,13 +283,14 @@ TEST(nigiri, rt_test) { {.stop_id_ = "E", .delay_minutes_ = 0, .skip_ = false}}}}, date::sys_days{2019_y / May / 1} + 9h)); EXPECT_EQ(1U, stats3.total_entities_success_); - auto const r3 = mn::route( - tags, tt, &rtt, - mn::make_routing_msg( - "tag_A", "tag_E", - mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min))); + auto const r3 = + mn::route(tags, tt, &rtt, + mn::make_routing_msg( + "tag_A", "tag_E", + mn::to_unix(date::sys_days{2019_y / May / 1} + 7h + 50min)), + metrics); auto const j3 = message_to_journeys(motis_content(RoutingResponse, r3)); ASSERT_EQ(1U, j3.size()); EXPECT_EQ(0U, j3[0].transfers_); EXPECT_EQ(5, j3[0].duration_); -} \ No newline at end of file +} diff --git a/modules/osr/src/osr.cc b/modules/osr/src/osr.cc index 15373233a..afc807add 100644 --- a/modules/osr/src/osr.cc +++ b/modules/osr/src/osr.cc @@ -4,6 +4,11 @@ #include "boost/thread/tss.hpp" +#include "fmt/format.h" + +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" + #include "utl/to_vec.h" #include "cista/reflection/comparable.h" @@ -18,6 +23,7 @@ #include "motis/core/common/logging.h" #include "motis/core/conv/position_conv.h" +#include "motis/core/otel/tracer.h" #include "motis/module/context/motis_spawn.h" #include "motis/module/event_collector.h" #include "motis/module/ini_io.h" @@ -67,6 +73,10 @@ void osr::init(mm::registry& reg) { mm::msg_ptr osr::table(mm::msg_ptr const& msg) const { using osrm::CreateOSRMManyToManyResponse; using osrm::OSRMManyToManyRequest; + + auto span = motis_tracer->StartSpan("osr::table"); + auto scope = opentelemetry::trace::Scope{span}; + auto const req = motis_content(OSRMManyToManyRequest, msg); auto const profile = o::to_profile(req->profile()->view()); @@ -100,6 +110,10 @@ mm::msg_ptr osr::table(mm::msg_ptr const& msg) const { mm::msg_ptr osr::one_to_many(mm::msg_ptr const& msg) const { using osrm::OSRMOneToManyRequest; + + auto span = motis_tracer->StartSpan("osr::one_to_many"); + auto scope = opentelemetry::trace::Scope{span}; + auto const req = motis_content(OSRMOneToManyRequest, msg); auto const from = o::location{from_fbs(req->one()), o::level_t::invalid()}; auto const to = utl::to_vec(*req->many(), [](auto&& x) { @@ -111,6 +125,15 @@ mm::msg_ptr osr::one_to_many(mm::msg_ptr const& msg) const { ? o::direction::kForward : o::direction::kBackward; + span->SetAttribute("motis.osr.request.profile", req->profile()->view()); + span->SetAttribute("motis.osr.request.from", fmt::format("{}", from.pos_)); + span->SetAttribute("motis.osr.request.to", + fmt::format("{}", utl::to_vec(to, [](auto const& loc) { + return loc.pos_; + }))); + span->SetAttribute("motis.osr.request.direction", + dir == o::direction::kForward ? "forward" : "backward"); + mm::message_creator fbb; fbb.create_and_finish( MsgContent_OSRMOneToManyResponse, @@ -133,6 +156,10 @@ mm::msg_ptr osr::one_to_many(mm::msg_ptr const& msg) const { mm::msg_ptr osr::via(mm::msg_ptr const& msg) const { using osrm::OSRMViaRouteRequest; + + auto span = motis_tracer->StartSpan("osr::via"); + auto scope = opentelemetry::trace::Scope{span}; + auto const req = motis_content(OSRMViaRouteRequest, msg); utl::verify(req->waypoints()->size() == 2U, "no via points supported"); @@ -142,10 +169,17 @@ mm::msg_ptr osr::via(mm::msg_ptr const& msg) const { o::location{from_fbs(req->waypoints()->Get(0)), o::level_t::invalid()}; auto const to = o::location{from_fbs(req->waypoints()->Get(1)), o::level_t::invalid()}; + + span->SetAttribute("motis.osr.request.profile", req->profile()->view()); + span->SetAttribute("motis.osr.request.from", fmt::format("{}", from.pos_)); + span->SetAttribute("motis.osr.request.to", fmt::format("{}", to.pos_)); + auto const result = o::route(*impl_->w_, *impl_->l_, profile, from, to, kMaxDist, o::direction::kForward, kMaxMatchDist); utl::verify(result.has_value(), "no path found"); + span->SetAttribute("motis.osr.result.segments", result->segments_.size()); + auto doubles = std::vector{}; for (auto const& s : result->segments_) { for (auto const& p : s.polyline_) { @@ -169,7 +203,11 @@ mm::msg_ptr osr::ppr(mm::msg_ptr const& msg) const { using ppr::FootRoutingRequest; using ppr::FootRoutingResponse; + auto span = motis_tracer->StartSpan("osr::ppr"); + auto scope = opentelemetry::trace::Scope{span}; + auto const req = motis_content(FootRoutingRequest, msg); + mm::message_creator fbb; if (req->include_path()) { fbb.create_and_finish( @@ -261,6 +299,9 @@ void osr::import(mm::import_dispatcher& reg) { mm::event_collector::publish_fn_t const& publish) { using import::OSMEvent; + auto span = motis_tracer->StartSpan("osr::import"); + auto scope = opentelemetry::trace::Scope{span}; + auto const osm = motis_content(OSMEvent, dependencies.at("OSM")); auto const state = import_state{data_path(osm->path()->str()), osm->hash(), osm->size()}; @@ -268,9 +309,15 @@ void osr::import(mm::import_dispatcher& reg) { auto const dir = get_data_directory() / "osr"; fs::create_directories(dir); + span->SetAttribute("motis.osm.file", osm->path()->str()); + span->SetAttribute("motis.osm.size", osm->size()); + if (mm::read_ini(dir / "import.ini") != state) { + span->SetAttribute("motis.import.state", "changed"); o::extract(false, osm->path()->str(), dir); mm::write_ini(dir / "import.ini", state); + } else { + span->SetAttribute("motis.import.state", "unchanged"); } auto w = std::make_unique(dir, cista::mmap::protection::READ); diff --git a/modules/ppr/src/ppr.cc b/modules/ppr/src/ppr.cc index eacac823f..b24d3d69a 100644 --- a/modules/ppr/src/ppr.cc +++ b/modules/ppr/src/ppr.cc @@ -4,10 +4,14 @@ #include #include #include +#include #include "cista/hash.h" #include "cista/mmap.h" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" + #include "utl/progress_tracker.h" #include "utl/to_vec.h" @@ -21,6 +25,7 @@ #include "motis/core/common/logging.h" #include "motis/core/schedule/time.h" +#include "motis/core/otel/tracer.h" #include "motis/module/event_collector.h" #include "motis/module/ini_io.h" @@ -177,6 +182,9 @@ struct ppr::impl { } msg_ptr route(msg_ptr const& msg) const { + auto span = motis_tracer->StartSpan("ppr::route"); + auto scope = opentelemetry::trace::Scope{span}; + switch (msg->get()->content_type()) { case MsgContent_FootRoutingRequest: return route_normal(msg); case MsgContent_FootRoutingSimpleRequest: return route_simple(msg); @@ -203,6 +211,9 @@ struct ppr::impl { private: msg_ptr route_normal(msg_ptr const& msg) const { + auto span = motis_tracer->StartSpan("ppr::route_normal"); + auto scope = opentelemetry::trace::Scope{span}; + auto const req = motis_content(FootRoutingRequest, msg); auto start = to_location(req->start()); @@ -211,11 +222,19 @@ struct ppr::impl { destinations.emplace_back(to_location(dest)); } - auto const profile = get_search_profile(req->search_options()); auto const dir = req->search_direction() == SearchDir_Forward ? search_direction::FWD : search_direction::BWD; + span->SetAttribute("motis.ppr.request.profile", + req->search_options()->profile()->view()); + span->SetAttribute("motis.ppr.request.duration_limit", + req->search_options()->duration_limit()); + span->SetAttribute("motis.ppr.request.direction", + dir == search_direction::FWD ? "forward" : "backward"); + + auto const profile = get_search_profile(req->search_options()); + auto const result = find_routes(data_.rg_, start, destinations, profile, dir); @@ -238,6 +257,9 @@ struct ppr::impl { } msg_ptr route_simple(msg_ptr const& msg) const { + auto span = motis_tracer->StartSpan("ppr::route_simple"); + auto scope = opentelemetry::trace::Scope{span}; + auto const req = motis_content(FootRoutingSimpleRequest, msg); auto start = to_location(req->start()); @@ -310,16 +332,23 @@ void ppr::import(import_dispatcher& reg) { using import::OSMEvent; using import::DEMEvent; + auto span = motis_tracer->StartSpan("ppr::import"); + auto scope = opentelemetry::trace::Scope{span}; + auto const dir = get_data_directory() / "ppr"; auto const osm = motis_content(OSMEvent, dependencies.at("OSM")); auto const osm_path = osm->path()->str(); + span->SetAttribute("motis.osm.file", osm_path); + span->SetAttribute("motis.osm.size", osm->size()); + auto dem_path = std::string{}; auto dem_hash = cista::hash_t{}; if (use_dem_) { auto const dem = motis_content(DEMEvent, dependencies.at("DEM")); dem_path = data_path(dem->path()->str()); dem_hash = dem->hash(); + span->SetAttribute("motis.dem.path", dem->path()->str()); } auto progress_tracker = utl::get_active_progress_tracker(); @@ -330,6 +359,9 @@ void ppr::import(import_dispatcher& reg) { auto const state_changed = read_ini(dir / "import.ini") != state; + span->SetAttribute("motis.import.state", + state_changed ? "changed" : "unchanged"); + auto const rtree_opt = lock_rtrees_ ? rtree_options::LOCK : (prefetch_rtrees_ ? rtree_options::PREFETCH @@ -347,6 +379,7 @@ void ppr::import(import_dispatcher& reg) { auto graph_size = std::size_t{}; auto const load_graph = [&]() { + span->AddEvent("load graph", {{"file", graph_file()}}); impl_ = std::make_unique( graph_file(), profiles, edge_rtree_max_size_, area_rtree_max_size_, rtree_opt, verify_graph_, check_integrity_); @@ -369,6 +402,8 @@ void ppr::import(import_dispatcher& reg) { try { load_graph(); } catch (std::exception const& e) { + span->AddEvent("exception", {{"exception.message", e.what()}, + {"during", "load_graph"}}); impl_.reset(); LOG(logging::error) << "loading existing ppr routing graph failed (" << e.what() << "), will be re-created"; @@ -376,6 +411,7 @@ void ppr::import(import_dispatcher& reg) { } if (!impl_) { + span->AddEvent("import"); fs::create_directories(dir); pp::options opt; @@ -391,22 +427,32 @@ void ppr::import(import_dispatcher& reg) { log.out_ = &std::clog; log.total_progress_updates_only_ = true; - log.step_started_ = [&progress_tracker](pp::logging const& log, - pp::step_info const& step) { + auto step_span = std::shared_ptr{}; + auto step_scope = std::unique_ptr{}; + + log.step_started_ = [&](pp::logging const& log, + pp::step_info const& step) { + step_span = motis_tracer->StartSpan( + step.name(), {{"step.current", (log.current_step() + 1)}, + {"step.total", log.step_count()}}); + step_scope = + std::make_unique(step_span); std::clog << "Step " << (log.current_step() + 1) << "/" << log.step_count() << ": " << step.name() << ": Starting" << '\n'; progress_tracker->status(step.name()); }; - log.step_progress_ = [&progress_tracker](pp::logging const& log, - pp::step_info const&) { + log.step_progress_ = [&](pp::logging const& log, + pp::step_info const&) { progress_tracker->update( static_cast(log.total_progress() * 100)); }; - log.step_finished_ = [](pp::logging const& log, - pp::step_info const& step) { + log.step_finished_ = [&](pp::logging const& log, + pp::step_info const& step) { + step_scope.reset(nullptr); + step_span.reset(); std::clog << "Step " << (log.current_step() + 1) << "/" << log.step_count() << ": " << step.name() << ": Finished in " << static_cast(step.duration_) diff --git a/modules/tiles/src/tiles.cc b/modules/tiles/src/tiles.cc index 2053b6d90..55c26e1e4 100644 --- a/modules/tiles/src/tiles.cc +++ b/modules/tiles/src/tiles.cc @@ -5,6 +5,9 @@ #include "lmdb/lmdb.hpp" +#include "opentelemetry/trace/scope.h" +#include "opentelemetry/trace/span.h" + #include "net/web_server/url_decode.h" #include "cista/reflection/comparable.h" @@ -24,6 +27,7 @@ #include "utl/progress_tracker.h" #include "utl/verify.h" +#include "motis/core/otel/tracer.h" #include "motis/module/event_collector.h" #include "motis/module/ini_io.h" @@ -78,6 +82,9 @@ void tiles::import(mm::import_dispatcher& reg) { get_data_directory().generic_string(), "tiles", reg, [this](mm::event_collector::dependencies_map_t const& dependencies, mm::event_collector::publish_fn_t const&) { + auto span = motis_tracer->StartSpan("tiles::import"); + auto scope = opentelemetry::trace::Scope{span}; + auto const profile_path = fs::path{profile_path_}; auto const profile_str = utl::read_file(profile_path.string().c_str()); utl::verify(profile_str.has_value(), "tiles::import cant read profile"); diff --git a/test/src/test_main.cc b/test/src/test_main.cc index 26edf1288..33c078d74 100644 --- a/test/src/test_main.cc +++ b/test/src/test_main.cc @@ -3,8 +3,12 @@ #include "gtest/gtest.h" +#include "opentelemetry/trace/provider.h" + #include "utl/progress_tracker.h" +#include "motis/core/otel/tracer.h" + #include "test_dir.h" #ifdef PROTOBUF_LINKED @@ -21,6 +25,9 @@ int main(int argc, char** argv) { fs::current_path(MOTIS_TEST_EXECUTION_DIR); std::cout << "executing tests in " << fs::current_path() << '\n'; + auto tracer_provider = opentelemetry::trace::Provider::GetTracerProvider(); + motis::motis_tracer = tracer_provider->GetTracer("motis-test"); + ::testing::InitGoogleTest(&argc, argv); auto test_result = RUN_ALL_TESTS();