diff --git a/Framework/Core/include/Framework/DeviceControl.h b/Framework/Core/include/Framework/DeviceControl.h index 589de3937ee55..ce946e8e77fbf 100644 --- a/Framework/Core/include/Framework/DeviceControl.h +++ b/Framework/Core/include/Framework/DeviceControl.h @@ -48,6 +48,8 @@ struct DeviceControl { DeviceController* controller = nullptr; /// What kind of events should run with the TRACE level int tracingFlags = 0; + /// What kind of log streams should be enabled + int logStreams = 0; /// An incremental number to identify the device state int requestedState = 0; }; diff --git a/Framework/Core/include/Framework/DeviceState.h b/Framework/Core/include/Framework/DeviceState.h index 3be0302fd4113..4fa72a84cad71 100644 --- a/Framework/Core/include/Framework/DeviceState.h +++ b/Framework/Core/include/Framework/DeviceState.h @@ -57,6 +57,13 @@ struct DeviceState { DATA_CONNECTED = 1 << 19, // Data channel connected }; + enum LogStreams : int { + NO_LOG = 0, + DEVICE_LOG = 1 << 0, // Log for Data Processing Device activities. + COMPLETION_LOG = 1 << 1, // Log for the completion policy of the device. + MONITORING_SERVICE_LOG = 1 << 2, // Log for the monitoring service flushing. + }; + std::vector inputChannelInfos; StreamingState streaming = StreamingState::Streaming; bool quitRequested = false; @@ -93,6 +100,8 @@ struct DeviceState { int loopReason = 0; /// Bitmask of LoopReason to trace int tracingFlags = 0; + /// Bitmask of log streams which are available + int logStreams = 0; /// Stack of the severity, so that we can display only /// the bits we are interested in. std::vector severityStack; diff --git a/Framework/Core/src/CompletionPolicyHelpers.cxx b/Framework/Core/src/CompletionPolicyHelpers.cxx index 8c4b38ba3355c..a6240b1165b81 100644 --- a/Framework/Core/src/CompletionPolicyHelpers.cxx +++ b/Framework/Core/src/CompletionPolicyHelpers.cxx @@ -18,10 +18,13 @@ #include "Framework/TimesliceIndex.h" #include "Framework/TimingInfo.h" #include "DecongestionService.h" +#include "Framework/Signpost.h" #include #include +O2_DECLARE_DYNAMIC_LOG(completion); + namespace o2::framework { @@ -108,6 +111,8 @@ CompletionPolicy CompletionPolicyHelpers::consumeWhenAll(const char* name, Compl { auto callback = [](InputSpan const& inputs, std::vector const& specs, ServiceRegistryRef& ref) -> CompletionPolicy::CompletionOp { assert(inputs.size() == specs.size()); + O2_SIGNPOST_ID_GENERATE(sid, completion); + O2_SIGNPOST_START(completion, sid, "consumeWhenAll", "Completion policy invoked"); size_t si = 0; bool missingSporadic = false; @@ -116,15 +121,18 @@ CompletionPolicy CompletionPolicyHelpers::consumeWhenAll(const char* name, Compl assert(si < specs.size()); auto& spec = specs[si++]; if (input.header == nullptr && spec.lifetime != Lifetime::Sporadic) { + O2_SIGNPOST_END(completion, sid, "consumeWhenAll", "Completion policy returned %{public}s due to missing input %lu", "Wait", si); return CompletionPolicy::CompletionOp::Wait; } if (input.header == nullptr && spec.lifetime == Lifetime::Sporadic) { + O2_SIGNPOST_EVENT_EMIT(completion, sid, "consumeWhenAll", "Missing sporadic found for route index %lu", si); missingSporadic = true; } if (input.header != nullptr && currentTimeslice == -1) { auto const* dph = framework::DataRefUtils::getHeader(input); if (dph && !TimingInfo::timesliceIsTimer(dph->startTime)) { currentTimeslice = dph->startTime; + O2_SIGNPOST_EVENT_EMIT(completion, sid, "consumeWhenAll", "currentTimeslice %lu from route index %lu", currentTimeslice, si); } } } @@ -134,8 +142,10 @@ CompletionPolicy CompletionPolicyHelpers::consumeWhenAll(const char* name, Compl auto oldestPossibleTimeslice = timesliceIndex.getOldestPossibleInput().timeslice.value; if (missingSporadic && currentTimeslice >= oldestPossibleTimeslice) { + O2_SIGNPOST_END(completion, sid, "consumeWhenAll", "Completion policy returned %{public}s for timeslice %lu > oldestPossibleTimeslice %lu", "Retry", currentTimeslice, oldestPossibleTimeslice); return CompletionPolicy::CompletionOp::Retry; } + O2_SIGNPOST_END(completion, sid, "consumeWhenAll", "Completion policy returned %{public}s for timeslice %lu <= oldestPossibleTimeslice %lu", "Consume", currentTimeslice, oldestPossibleTimeslice); return CompletionPolicy::CompletionOp::Consume; }; return CompletionPolicy{name, matcher, callback}; diff --git a/Framework/Core/src/DataProcessingDevice.cxx b/Framework/Core/src/DataProcessingDevice.cxx index b03904c5b3776..366bfafd7d801 100644 --- a/Framework/Core/src/DataProcessingDevice.cxx +++ b/Framework/Core/src/DataProcessingDevice.cxx @@ -35,6 +35,9 @@ #include "Framework/TMessageSerializer.h" #include "Framework/InputRecord.h" #include "Framework/InputSpan.h" +#if defined(__APPLE__) || defined(NDEBUG) +#define O2_SIGNPOST_IMPLEMENTATION +#endif #include "Framework/Signpost.h" #include "Framework/TimingHelpers.h" #include "Framework/SourceInfoHeader.h" @@ -80,6 +83,8 @@ #include #include +O2_DECLARE_DYNAMIC_LOG(device); + using namespace o2::framework; using ConfigurationInterface = o2::configuration::ConfigurationInterface; using DataHeader = o2::header::DataHeader; @@ -274,21 +279,22 @@ struct PollerContext { void on_socket_polled(uv_poll_t* poller, int status, int events) { auto* context = (PollerContext*)poller->data; + assert(context); + O2_SIGNPOST_ID_FROM_POINTER(sid, device, poller); context->state->loopReason |= DeviceState::DATA_SOCKET_POLLED; switch (events) { case UV_READABLE: { - ZoneScopedN("socket readable event"); - LOG(debug) << "socket polled UV_READABLE: " << context->name; + O2_SIGNPOST_EVENT_EMIT(device, sid, "socket_state", "Data pending on socket for channel %{public}s", context->name); context->state->loopReason |= DeviceState::DATA_INCOMING; } break; case UV_WRITABLE: { - ZoneScopedN("socket writeable"); + O2_SIGNPOST_END(device, sid, "socket_state", "Socket connected for channel %{public}s", context->name); if (context->read) { - LOG(debug) << "socket polled UV_CONNECT" << context->name; + O2_SIGNPOST_START(device, sid, "socket_state", "Socket connected for read in context %{public}s", context->name); uv_poll_start(poller, UV_READABLE | UV_DISCONNECT | UV_PRIORITIZED, &on_socket_polled); context->state->loopReason |= DeviceState::DATA_CONNECTED; } else { - LOG(debug) << "socket polled UV_WRITABLE" << context->name; + O2_SIGNPOST_START(device, sid, "socket_state", "Socket connected for write for channel %{public}s", context->name); context->state->loopReason |= DeviceState::DATA_OUTGOING; // If the socket is writable, fairmq will handle the rest, so we can stop polling and // just wait for the disconnect. @@ -297,12 +303,10 @@ void on_socket_polled(uv_poll_t* poller, int status, int events) context->pollerState = PollerContext::PollerState::Connected; } break; case UV_DISCONNECT: { - ZoneScopedN("socket disconnect"); - LOG(debug) << "socket polled UV_DISCONNECT"; + O2_SIGNPOST_END(device, sid, "socket_state", "Socket disconnected in context %{public}s", context->name); } break; case UV_PRIORITIZED: { - ZoneScopedN("socket prioritized"); - LOG(debug) << "socket polled UV_PRIORITIZED"; + O2_SIGNPOST_EVENT_EMIT(device, sid, "socket_state", "Data pending on socket for context %{public}s", context->name); } break; } // We do nothing, all the logic for now stays in DataProcessingDevice::doRun() @@ -873,7 +877,9 @@ void DataProcessingDevice::startPollers() auto& deviceContext = ref.get(); auto& state = ref.get(); - for (auto& poller : state.activeInputPollers) { + for (auto* poller : state.activeInputPollers) { + O2_SIGNPOST_ID_FROM_POINTER(sid, device, poller); + O2_SIGNPOST_START(device, sid, "socket_state", "Input socket waiting for connection."); uv_poll_start(poller, UV_WRITABLE, &on_socket_polled); ((PollerContext*)poller->data)->pollerState = PollerContext::PollerState::Disconnected; } @@ -881,7 +887,9 @@ void DataProcessingDevice::startPollers() uv_poll_start(poller, UV_WRITABLE, &on_out_of_band_polled); ((PollerContext*)poller->data)->pollerState = PollerContext::PollerState::Disconnected; } - for (auto& poller : state.activeOutputPollers) { + for (auto* poller : state.activeOutputPollers) { + O2_SIGNPOST_ID_FROM_POINTER(sid, device, poller); + O2_SIGNPOST_START(device, sid, "socket_state", "Output socket waiting for connection."); uv_poll_start(poller, UV_WRITABLE, &on_socket_polled); ((PollerContext*)poller->data)->pollerState = PollerContext::PollerState::Disconnected; } @@ -897,17 +905,21 @@ void DataProcessingDevice::stopPollers() auto& deviceContext = ref.get(); auto& state = ref.get(); LOGP(detail, "Stopping {} input pollers", state.activeInputPollers.size()); - for (auto& poller : state.activeInputPollers) { + for (auto* poller : state.activeInputPollers) { + O2_SIGNPOST_ID_FROM_POINTER(sid, device, poller); + O2_SIGNPOST_END(device, sid, "socket_state", "Output socket closed."); uv_poll_stop(poller); ((PollerContext*)poller->data)->pollerState = PollerContext::PollerState::Stopped; } LOGP(detail, "Stopping {} out of band pollers", state.activeOutOfBandPollers.size()); - for (auto& poller : state.activeOutOfBandPollers) { + for (auto* poller : state.activeOutOfBandPollers) { uv_poll_stop(poller); ((PollerContext*)poller->data)->pollerState = PollerContext::PollerState::Stopped; } LOGP(detail, "Stopping {} output pollers", state.activeOutOfBandPollers.size()); - for (auto& poller : state.activeOutputPollers) { + for (auto* poller : state.activeOutputPollers) { + O2_SIGNPOST_ID_FROM_POINTER(sid, device, poller); + O2_SIGNPOST_END(device, sid, "socket_state", "Output socket closed."); uv_poll_stop(poller); ((PollerContext*)poller->data)->pollerState = PollerContext::PollerState::Stopped; } diff --git a/Framework/Core/src/WSDriverClient.cxx b/Framework/Core/src/WSDriverClient.cxx index d4ed77b9a004e..ac2e3db41fcef 100644 --- a/Framework/Core/src/WSDriverClient.cxx +++ b/Framework/Core/src/WSDriverClient.cxx @@ -16,10 +16,15 @@ #include "Framework/DeviceSpec.h" #include "DriverClientContext.h" #include "DPLWebSocket.h" +#include "Framework/Signpost.h" #include #include #include +O2_DECLARE_DYNAMIC_LOG(device); +O2_DECLARE_DYNAMIC_LOG(completion); +O2_DECLARE_DYNAMIC_LOG(monitoring_service); + namespace o2::framework { @@ -152,6 +157,41 @@ void on_connect(uv_connect_t* connection, int status) state.tracingFlags = tracingFlags; }); + client->observe("/log-streams", [ref = context->ref](std::string_view cmd) { + auto& state = ref.get(); + static constexpr int prefixSize = std::string_view{"/log-streams "}.size(); + if (prefixSize > cmd.size()) { + LOG(error) << "Malformed log-streams request"; + return; + } + cmd.remove_prefix(prefixSize); + int logStreams = 0; + + auto error = std::from_chars(cmd.data(), cmd.data() + cmd.size(), logStreams); + if (error.ec != std::errc()) { + LOG(error) << "Malformed log-streams mask"; + return; + } + LOGP(info, "Logstreams flags set to {}", logStreams); + state.logStreams = logStreams; + if ((state.logStreams & DeviceState::LogStreams::DEVICE_LOG) != 0) { + O2_LOG_ENABLE(device); + } else { + O2_LOG_DISABLE(device); + } + if ((state.logStreams & DeviceState::LogStreams::COMPLETION_LOG) != 0) { + O2_LOG_ENABLE(completion); + } else { + O2_LOG_DISABLE(completion); + } + + if ((state.logStreams & DeviceState::LogStreams::MONITORING_SERVICE_LOG) != 0) { + O2_LOG_ENABLE(monitoring_service); + } else { + O2_LOG_DISABLE(monitoring_service); + } + }); + // Client will be filled in the line after. I can probably have a single // client per device. auto dplClient = std::make_unique(); diff --git a/Framework/Foundation/include/Framework/Signpost.h b/Framework/Foundation/include/Framework/Signpost.h index eca9e26f77469..d2bdec0ec8246 100644 --- a/Framework/Foundation/include/Framework/Signpost.h +++ b/Framework/Foundation/include/Framework/Signpost.h @@ -13,6 +13,9 @@ #include #include +#ifdef __APPLE__ +#include +#endif struct o2_log_handle_t { char const* name = nullptr; @@ -22,6 +25,7 @@ struct o2_log_handle_t { // Helper function which replaces engineering types with a printf // compatible format string. +// FIXME: make this consteval when available in C++20 template constexpr auto remove_engineering_type(char const (&src)[N]) { @@ -82,78 +86,37 @@ o2_log_handle_t* o2_walk_logs(bool (*callback)(char const* name, void* log, void } #endif -#if !defined(O2_FORCE_LOGGER_SIGNPOST) && defined(__APPLE__) && (!defined(NDEBUG) || defined(O2_FORCE_SIGNPOSTS)) +#if defined(__APPLE__) #include #include #include -void* _o2_log_create(char const* name, char const* category); -#define O2_DECLARE_DYNAMIC_LOG(x) static os_log_t private_o2_log_##x = (os_log_t)_o2_log_create("ch.cern.aliceo2." #x, OS_LOG_CATEGORY_DYNAMIC_TRACING) -#define O2_DECLARE_DYNAMIC_STACKTRACE_LOG(x) static os_log_t private_o2_log_##x = (os_log_t)_o2_log_create("ch.cern.aliceo2." #x, OS_LOG_CATEGORY_DYNAMIC_STACK_TRACING) -// This is a no-op on macOS using the os_signpost API because only external instruments can enable/disable dynamic signposts -#define O2_LOG_ENABLE_DYNAMIC(log) -// This is a no-op on macOS using the os_signpost API because only external instruments can enable/disable dynamic signposts -#define O2_LOG_ENABLE_STACKTRACE(log) -#define O2_DECLARE_LOG(x, category) static os_log_t private_o2_log_##x = (os_log_t)_o2_log_create("ch.cern.aliceo2." #x, #category) -#define O2_LOG_DEBUG(log, ...) os_log_debug(private_o2_log_##log, __VA_ARGS__) -#define O2_SIGNPOST_ID_FROM_POINTER(name, log, pointer) os_signpost_id_t name = os_signpost_id_make_with_pointer(private_o2_log_##log, pointer) -#define O2_SIGNPOST_ID_GENERATE(name, log) os_signpost_id_t name = os_signpost_id_generate(private_o2_log_##log) +#define O2_LOG_DEBUG_MAC(log, ...) os_log_debug(private_o2_log_##log, __VA_ARGS__) // FIXME: use __VA_OPT__ when available in C++20 -#define O2_SIGNPOST_EVENT_EMIT(log, id, name, format, ...) os_signpost_event_emit(private_o2_log_##log, id, name, format, ##__VA_ARGS__) -#define O2_SIGNPOST_START(log, id, name, format, ...) os_signpost_interval_begin(private_o2_log_##log, id, name, format, ##__VA_ARGS__) -#define O2_SIGNPOST_END(log, id, name, format, ...) os_signpost_interval_end(private_o2_log_##log, id, name, format, ##__VA_ARGS__) - -#ifdef O2_SIGNPOST_IMPLEMENTATION -/// We use a wrapper so that we can keep track of the logs. -void* _o2_log_create(char const* name, char const* category) -{ - // iterate over the list of logs and check if we already have - // one with the same name. - auto findLogByName = [](char const* name, void* log, void* context) -> bool { - char const* currentName = (char const*)context; - if (strcmp(name, currentName) == 0) { - return false; - } - return true; - }; - - o2_log_handle_t* handle = o2_walk_logs(findLogByName, (void*)name); - - // If we found one, return it. - if (handle) { - return handle->log; - } - // Otherwise, create a new one and add it to the end of the list. - os_log_t log = os_log_create(name, category); - o2_log_handle_t* newHandle = new o2_log_handle_t(); - newHandle->log = log; - newHandle->name = strdup(name); - newHandle->next = o2_get_logs_tail().load(); - // Until I manage to replace the log I have in next, keep trying. - // Notice this does not protect against two threads trying to insert - // a log with the same name. I should probably do a sorted insert for that. - while (!o2_get_logs_tail().compare_exchange_weak(newHandle->next, newHandle, - std::memory_order_release, - std::memory_order_relaxed)) { - newHandle->next = o2_get_logs_tail(); - } - - return log; -} +#define O2_SIGNPOST_EVENT_EMIT_MAC(log, id, name, format, ...) os_signpost_event_emit(private_o2_log_##log->os_log, (uint64_t)id.value, name, format, ##__VA_ARGS__) +#define O2_SIGNPOST_START_MAC(log, id, name, format, ...) os_signpost_interval_begin(private_o2_log_##log->os_log, (uint64_t)id.value, name, format, ##__VA_ARGS__) +#define O2_SIGNPOST_END_MAC(log, id, name, format, ...) os_signpost_interval_end(private_o2_log_##log->os_log, (uint64_t)id.value, name, format, ##__VA_ARGS__) +#define O2_SIGNPOST_ENABLED_MAC(log) os_signpost_enabled(private_o2_log_##log->os_log) +#else +// These are no-ops on linux. +#define O2_DECLARE_LOG_MAC(x, category) +#define O2_LOG_DEBUG_MAC(log, ...) +#define O2_SIGNPOST_EVENT_EMIT_MAC(log, id, name, format, ...) +#define O2_SIGNPOST_START_MAC(log, id, name, format, ...) +#define O2_SIGNPOST_END_MAC(log, id, name, format, ...) +#define O2_SIGNPOST_ENABLED_MAC(log) false +#endif // __APPLE__ + +// Unless we are on apple we enable checking for signposts only if in debug mode or if we force them. +#if defined(__APPLE__) || defined(O2_FORCE_SIGNPOSTS) || !defined(NDEBUG) +#define O2_LOG_ENABLED(log) private_o2_log_##log->stacktrace +#else +#define O2_LOG_ENABLED(log) false #endif -#elif !defined(NDEBUG) || defined(O2_FORCE_LOGGER_SIGNPOST) || defined(O2_FORCE_SIGNPOSTS) - -#ifndef O2_LOG_MACRO -#if __has_include("Framework/Logger.h") +#if !defined(O2_LOG_MACRO) && __has_include("Framework/Logger.h") #include "Framework/Logger.h" -// If NDEBUG is not defined, we use the logger to print out the signposts at the debug level. -#if !defined(NDEBUG) -#define O2_LOG_MACRO(...) LOGF(debug, __VA_ARGS__) -#elif defined(O2_FORCE_LOGGER_SIGNPOST) || defined(O2_FORCE_SIGNPOSTS) -// If we force the presence of the logger, we use it to print out the signposts at the detail level, which is not optimized out. #define O2_LOG_MACRO(...) LOGF(info, __VA_ARGS__) -#endif -#else +#elif !defined(O2_LOG_MACRO) // If we do not have the fairlogger, we simply print out the signposts to the console. // This is useful for things like the tests, which this way do not need to depend on the FairLogger. #define O2_LOG_MACRO(...) \ @@ -161,8 +124,9 @@ void* _o2_log_create(char const* name, char const* category) printf(__VA_ARGS__); \ printf("\n"); \ } while (0) -#endif -#endif +#else +#define O2_LOG_MACRO(...) +#endif // O2_LOG_MACRO // This is the linux implementation, it is not as nice as the apple one and simply prints out // the signpost information to the log. @@ -181,7 +145,7 @@ struct _o2_lock_free_stack { // A log is simply an inbox which keeps track of the available id, so that we can print out different signposts // with different indentation levels. // supports up to 1024 paralle signposts before it spinlocks. -typedef int _o2_signpost_index_t; +using _o2_signpost_index_t = int; struct _o2_activity_t { // How much the activity is indented in the output log. @@ -191,10 +155,13 @@ struct _o2_activity_t { struct _o2_signpost_id_t { // The id of the activity. - int64_t id = -1; + int64_t value = -1; }; struct _o2_log_t { +#ifdef __APPLE__ + os_log_t os_log = nullptr; +#endif // A circular buffer of available slots. Each unique interval pulls an id from this buffer. _o2_lock_free_stack slots; // Up to 256 activities can be active at the same time. @@ -211,14 +178,16 @@ struct _o2_log_t { // 0 means the log is disabled. // 1 means only the current signpost is printed. // >1 means the current signpost and n levels of the stacktrace are printed. - std::atomic stacktrace = 1; + std::atomic stacktrace = 0; + + // Default stacktrace level for the log, when enabled. + int defaultStacktrace = 1; }; bool _o2_lock_free_stack_push(_o2_lock_free_stack& stack, const int& value, bool spin = false); bool _o2_lock_free_stack_pop(_o2_lock_free_stack& stack, int& value, bool spin = false); //_o2_signpost_id_t _o2_signpost_id_generate_local(_o2_log_t* log); //_o2_signpost_id_t _o2_signpost_id_make_with_pointer(_o2_log_t* log, void* pointer); -_o2_signpost_index_t o2_signpost_id_make_with_pointer(_o2_log_t* log, void* pointer); void* _o2_log_create(char const* name, int stacktrace); void _o2_signpost_event_emit(_o2_log_t* log, _o2_signpost_id_t id, char const* name, char const* const format, ...); void _o2_signpost_interval_begin(_o2_log_t* log, _o2_signpost_id_t id, char const* name, char const* const format, ...); @@ -246,14 +215,6 @@ inline _o2_signpost_id_t _o2_signpost_id_make_with_pointer(_o2_log_t* log, void* return uniqueId; } -inline _o2_signpost_index_t o2_signpost_id_make_with_pointer(_o2_log_t* log, void* pointer) -{ - _o2_signpost_index_t signpost_index; - _o2_lock_free_stack_pop(log->slots, signpost_index, true); - log->ids[signpost_index].id = (int64_t)pointer; - return signpost_index; -} - // Implementation start here. Include this file with O2_SIGNPOST_IMPLEMENTATION defined in one file of your // project. #ifdef O2_SIGNPOST_IMPLEMENTATION @@ -319,7 +280,7 @@ bool _o2_lock_free_stack_pop(_o2_lock_free_stack& stack, int& value, bool spin) } } -void* _o2_log_create(char const* name, int stacktrace) +void* _o2_log_create(char const* name, int defaultStacktrace) { // iterate over the list of logs and check if we already have // one with the same name. @@ -337,7 +298,7 @@ void* _o2_log_create(char const* name, int stacktrace) return handle->log; } // Otherwise, create a new one and add it to the end of the list. - _o2_log_t* log = new _o2_log_t(); + auto* log = new _o2_log_t(); // Write the initial 256 ids to the inbox, in reverse, so that the // linear search below is just for an handful of elements. int n = _o2_lock_free_stack::N; @@ -345,9 +306,18 @@ void* _o2_log_create(char const* name, int stacktrace) _o2_signpost_index_t signpost_index{n - 1 - i}; _o2_lock_free_stack_push(log->slots, signpost_index, true); } - log->stacktrace = stacktrace; - o2_log_handle_t* newHandle = new o2_log_handle_t(); + log->defaultStacktrace = defaultStacktrace; + auto* newHandle = new o2_log_handle_t(); newHandle->log = log; +#ifdef __APPLE__ + // On macOS, we use the os_signpost API so that when we are + // using instruments we can see the messages there. + if (defaultStacktrace > 1) { + log->os_log = os_log_create(name, OS_LOG_CATEGORY_DYNAMIC_STACK_TRACING); + } else { + log->os_log = os_log_create(name, OS_LOG_CATEGORY_DYNAMIC_TRACING); + } +#endif newHandle->name = strdup(name); newHandle->next = o2_get_logs_tail().load(); // Until I manage to replace the log I have in next, keep trying. @@ -366,10 +336,6 @@ void* _o2_log_create(char const* name, int stacktrace) // If the slot is empty, it will return the id and increment the indentation level. void _o2_signpost_event_emit(_o2_log_t* log, _o2_signpost_id_t id, char const* name, char const* const format, ...) { - // Nothing to be done - if (log->stacktrace == 0) { - return; - } va_list args; va_start(args, format); @@ -377,10 +343,10 @@ void _o2_signpost_event_emit(_o2_log_t* log, _o2_signpost_id_t id, char const* n int leading = 0; // This is the equivalent of exclusive - if (id.id != 0) { + if (id.value != 0) { int i = 0; for (i = 0; i < log->ids.size(); ++i) { - if (log->ids[i].id == id.id) { + if (log->ids[i].value == id.value) { break; } } @@ -394,7 +360,7 @@ void _o2_signpost_event_emit(_o2_log_t* log, _o2_signpost_id_t id, char const* n } char prebuffer[4096]; - int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16s*>%*c", id.id, name, leading, ' '); + int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16s*>%*c", id.value, name, leading, ' '); vsnprintf(prebuffer + s, 4096 - s, format, args); va_end(args); O2_LOG_MACRO("%s", prebuffer); @@ -404,22 +370,19 @@ void _o2_signpost_event_emit(_o2_log_t* log, _o2_signpost_id_t id, char const* n // If the slot is empty, it will return the id and increment the indentation level. void _o2_signpost_interval_begin(_o2_log_t* log, _o2_signpost_id_t id, char const* name, char const* const format, ...) { - if (log->stacktrace == 0) { - return; - } va_list args; va_start(args, format); // This is a unique slot for this interval. _o2_signpost_index_t signpost_index; _o2_lock_free_stack_pop(log->slots, signpost_index, true); // Put the id in the slot, to close things or to attach signposts to a given interval - log->ids[signpost_index].id = id.id; + log->ids[signpost_index].value = id.value; auto* activity = &log->activities[signpost_index]; activity->indentation = log->current_indentation++; activity->name = name; int leading = activity->indentation * 2; char prebuffer[4096]; - int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16sS>%*c", id.id, name, leading, ' '); + int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16sS>%*c", id.value, name, leading, ' '); vsnprintf(prebuffer + s, 4096 - s, format, args); va_end(args); O2_LOG_MACRO("%s", prebuffer); @@ -433,7 +396,7 @@ void _o2_signpost_interval_end_v(_o2_log_t* log, _o2_signpost_id_t id, char cons // Find the index of the activity int i = 0; for (i = 0; i < log->ids.size(); ++i) { - if (log->ids[i].id == id.id) { + if (log->ids[i].value == id.value) { break; } } @@ -448,13 +411,13 @@ void _o2_signpost_interval_end_v(_o2_log_t* log, _o2_signpost_id_t id, char cons _o2_activity_t* activity = &log->activities[i]; int leading = activity->indentation * 2; char prebuffer[4096]; - int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16sE>%*c", id.id, name, leading, ' '); + int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16sE>%*c", id.value, name, leading, ' '); vsnprintf(prebuffer + s, 4096 - s, format, args); O2_LOG_MACRO("%s", prebuffer); // Clear the slot activity->indentation = -1; activity->name = nullptr; - log->ids[i].id = -1; + log->ids[i].value = -1; // Put back the slot log->current_indentation--; _o2_signpost_index_t signpost_index{i}; @@ -477,29 +440,50 @@ void _o2_log_set_stacktrace(_o2_log_t* log, int stacktrace) } #endif // O2_SIGNPOST_IMPLEMENTATION -/// Dynamic logs need to be enabled via the O2_LOG_ENABLE_DYNAMIC macro. Notice this will only work +#if defined(__APPLE__) || defined(O2_FORCE_SIGNPOSTS) || !defined(NDEBUG) +/// Dynamic logs need to be enabled via the O2_LOG_ENABLE macro. Notice this will only work /// for the logger based logging, since the Apple version needs instruments to enable them. -#define O2_DECLARE_DYNAMIC_LOG(name) static _o2_log_t* private_o2_log_##name = (_o2_log_t*)_o2_log_create("ch.cern.aliceo2." #name, 0) +#define O2_DECLARE_DYNAMIC_LOG(name) static _o2_log_t* private_o2_log_##name = (_o2_log_t*)_o2_log_create("ch.cern.aliceo2." #name, 1) /// For the moment we do not support logs with a stacktrace. -#define O2_DECLARE_DYNAMIC_STACKTRACE_LOG(name) static _o2_log_t* private_o2_log_##name = (_o2_log_t*)_o2_log_create("ch.cern.aliceo2." #name, 0) +#define O2_DECLARE_DYNAMIC_STACKTRACE_LOG(name) static _o2_log_t* private_o2_log_##name = (_o2_log_t*)_o2_log_create("ch.cern.aliceo2." #name, 64) #define O2_DECLARE_LOG(name, category) static _o2_log_t* private_o2_log_##name = (_o2_log_t*)_o2_log_create("ch.cern.aliceo2." #name, 1) -#define O2_LOG_ENABLE_DYNAMIC(log) _o2_log_set_stacktrace(private_o2_log_##log, 1) -// We print out only the first 64 frames. -#define O2_LOG_ENABLE_STACKTRACE(log) _o2_log_set_stacktrace(private_o2_log_##log, 64) +// When we enable the log, we set the stacktrace to the default value. +#define O2_LOG_ENABLE(log) _o2_log_set_stacktrace(private_o2_log_##log, private_o2_log_##log->defaultStacktrace) +#define O2_LOG_DISABLE(log) _o2_log_set_stacktrace(private_o2_log_##log, 0) // For the moment we simply use LOG DEBUG. We should have proper activities so that we can // turn on and off the printing. #define O2_LOG_DEBUG(log, ...) O2_LOG_MACRO(__VA_ARGS__) #define O2_SIGNPOST_ID_FROM_POINTER(name, log, pointer) _o2_signpost_id_t name = _o2_signpost_id_make_with_pointer(private_o2_log_##log, pointer) #define O2_SIGNPOST_ID_GENERATE(name, log) _o2_signpost_id_t name = _o2_signpost_id_generate_local(private_o2_log_##log) -#define O2_SIGNPOST_EVENT_EMIT(log, id, name, format, ...) _o2_signpost_event_emit(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__) -#define O2_SIGNPOST_START(log, id, name, format, ...) _o2_signpost_interval_begin(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__) -#define O2_SIGNPOST_END(log, id, name, format, ...) _o2_signpost_interval_end(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__) +// In case Instruments is attached, we switch to the Apple signpost API otherwise, both one +// mac and on linux we use our own implementation, using the logger. We can use the same ids because +// they are compatible between the two implementations, we also use remove_engineering_type to remove +// the engineering types from the format string, so that we can use the same format string for both. +#define O2_SIGNPOST_EVENT_EMIT(log, id, name, format, ...) __extension__({ \ + if (O2_SIGNPOST_ENABLED_MAC(log)) { \ + O2_SIGNPOST_EVENT_EMIT_MAC(log, id, name, format, ##__VA_ARGS__); \ + } else if (private_o2_log_##log->stacktrace) { \ + _o2_signpost_event_emit(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__); \ + } \ +}) +#define O2_SIGNPOST_START(log, id, name, format, ...) \ + if (O2_SIGNPOST_ENABLED_MAC(log)) { \ + O2_SIGNPOST_START_MAC(log, id, name, format, ##__VA_ARGS__); \ + } else if (private_o2_log_##log->stacktrace) { \ + _o2_signpost_interval_begin(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__); \ + } +#define O2_SIGNPOST_END(log, id, name, format, ...) \ + if (O2_SIGNPOST_ENABLED_MAC(log)) { \ + O2_SIGNPOST_END_MAC(log, id, name, format, ##__VA_ARGS__); \ + } else if (private_o2_log_##log->stacktrace) { \ + _o2_signpost_interval_end(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__); \ + } #else // This is the release implementation, it does nothing. #define O2_DECLARE_DYNAMIC_LOG(x) #define O2_DECLARE_DYNAMIC_STACKTRACE_LOG(x) #define O2_DECLARE_LOG(x, category) -#define O2_LOG_ENABLE_DYNAMIC(log) -#define O2_LOG_ENABLE_STACKTRACE(log) +#define O2_LOG_ENABLE(log) +#define O2_LOG_DISABLE(log) #define O2_LOG_DEBUG(log, ...) #define O2_SIGNPOST_ID_FROM_POINTER(name, log, pointer) #define O2_SIGNPOST_ID_GENERATE(name, log) diff --git a/Framework/Foundation/test/test_Signpost.cxx b/Framework/Foundation/test/test_Signpost.cxx index 24b6afaec5c3d..f9b8d4ec0e13a 100644 --- a/Framework/Foundation/test/test_Signpost.cxx +++ b/Framework/Foundation/test/test_Signpost.cxx @@ -43,7 +43,7 @@ int main(int argc, char** argv) O2_SIGNPOST_START(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will not see, because they are off by default"); O2_SIGNPOST_END(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will not see, because they are off by default"); - O2_LOG_ENABLE_DYNAMIC(test_SignpostDynamic); + O2_LOG_ENABLE(test_SignpostDynamic); #ifdef __APPLE__ // On Apple there is no way to turn on signposts in the logger, so we do not display this message O2_SIGNPOST_START(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will see, because we turned them on"); diff --git a/Framework/Foundation/test/test_SignpostLogger.cxx b/Framework/Foundation/test/test_SignpostLogger.cxx index 74da35abf7c70..ed917ea7cadf5 100644 --- a/Framework/Foundation/test/test_SignpostLogger.cxx +++ b/Framework/Foundation/test/test_SignpostLogger.cxx @@ -51,7 +51,7 @@ int main(int argc, char** argv) O2_SIGNPOST_START(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will not see, because they are off by default"); O2_SIGNPOST_END(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will not see, because they are off by default"); - O2_LOG_ENABLE_DYNAMIC(test_SignpostDynamic); + O2_LOG_ENABLE(test_SignpostDynamic); #ifdef __APPLE__ // On Apple there is no way to turn on signposts in the logger, so we do not display this message O2_SIGNPOST_START(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will see, because we turned them on"); diff --git a/Framework/GUISupport/src/FrameworkGUIDeviceInspector.cxx b/Framework/GUISupport/src/FrameworkGUIDeviceInspector.cxx index a82753eb5af1f..fe93ca6d0f07f 100644 --- a/Framework/GUISupport/src/FrameworkGUIDeviceInspector.cxx +++ b/Framework/GUISupport/src/FrameworkGUIDeviceInspector.cxx @@ -400,6 +400,17 @@ void displayDeviceInspector(DeviceSpec const& spec, } } + bool logsChanged = false; + if (ImGui::CollapsingHeader("Signposts", ImGuiTreeNodeFlags_DefaultOpen)) { + logsChanged = ImGui::CheckboxFlags("Device", &control.logStreams, DeviceState::LogStreams::DEVICE_LOG); + logsChanged = ImGui::CheckboxFlags("Completion", &control.logStreams, DeviceState::LogStreams::COMPLETION_LOG); + logsChanged = ImGui::CheckboxFlags("Monitoring", &control.logStreams, DeviceState::LogStreams::MONITORING_SERVICE_LOG); + if (logsChanged && control.controller) { + std::string cmd = fmt::format("/log-streams {}", control.logStreams); + control.controller->write(cmd.c_str(), cmd.size()); + } + } + bool flagsChanged = false; if (ImGui::CollapsingHeader("Event loop tracing", ImGuiTreeNodeFlags_DefaultOpen)) { flagsChanged |= ImGui::CheckboxFlags("METRICS_MUST_FLUSH", &control.tracingFlags, DeviceState::LoopReason::METRICS_MUST_FLUSH); diff --git a/Framework/TestWorkflows/test/test_DetectMissingTimeframe.cxx b/Framework/TestWorkflows/test/test_DetectMissingTimeframe.cxx index 3374cd9ad6cf2..7ef1370f040b4 100644 --- a/Framework/TestWorkflows/test/test_DetectMissingTimeframe.cxx +++ b/Framework/TestWorkflows/test/test_DetectMissingTimeframe.cxx @@ -43,6 +43,7 @@ WorkflowSpec defineDataProcessing(ConfigContext const& specs) if (i++ % 2 == 0) { outputs.make(OutputRef{"a2"}, 1); } + sleep(1); })}, }; DataProcessorSpec d{