Skip to content

Commit dccea09

Browse files
ktfktf
committed
DPL: rework signposts support
The logger based Signposts are now behaving the same on macOS and linux when running normally. The difference between the two implementations will now be that if Instruments enables some OSLog namespace, we stop printing the messages and use the os_signpost API instead.
1 parent de4661d commit dccea09

3 files changed

Lines changed: 94 additions & 101 deletions

File tree

‎Framework/Foundation/include/Framework/Signpost.h‎

Lines changed: 92 additions & 99 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,9 @@
1313

1414
#include <atomic>
1515
#include <array>
16+
#ifdef __APPLE__
17+
#include <os/log.h>
18+
#endif
1619

1720
struct o2_log_handle_t {
1821
char const* name = nullptr;
@@ -22,6 +25,7 @@ struct o2_log_handle_t {
2225

2326
// Helper function which replaces engineering types with a printf
2427
// compatible format string.
28+
// FIXME: make this consteval when available in C++20
2529
template <auto N>
2630
constexpr auto remove_engineering_type(char const (&src)[N])
2731
{
@@ -82,87 +86,47 @@ o2_log_handle_t* o2_walk_logs(bool (*callback)(char const* name, void* log, void
8286
}
8387
#endif
8488

85-
#if !defined(O2_FORCE_LOGGER_SIGNPOST) && defined(__APPLE__) && (!defined(NDEBUG) || defined(O2_FORCE_SIGNPOSTS))
89+
#if defined(__APPLE__)
8690
#include <os/log.h>
8791
#include <os/signpost.h>
8892
#include <cstring>
89-
void* _o2_log_create(char const* name, char const* category);
90-
#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)
91-
#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)
92-
// This is a no-op on macOS using the os_signpost API because only external instruments can enable/disable dynamic signposts
93-
#define O2_LOG_ENABLE_DYNAMIC(log)
94-
// This is a no-op on macOS using the os_signpost API because only external instruments can enable/disable dynamic signposts
95-
#define O2_LOG_ENABLE_STACKTRACE(log)
96-
#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)
97-
#define O2_LOG_DEBUG(log, ...) os_log_debug(private_o2_log_##log, __VA_ARGS__)
98-
#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)
99-
#define O2_SIGNPOST_ID_GENERATE(name, log) os_signpost_id_t name = os_signpost_id_generate(private_o2_log_##log)
93+
#define O2_LOG_DEBUG_MAC(log, ...) os_log_debug(private_o2_log_##log, __VA_ARGS__)
10094
// FIXME: use __VA_OPT__ when available in C++20
101-
#define O2_SIGNPOST_EVENT_EMIT(log, id, name, format, ...) os_signpost_event_emit(private_o2_log_##log, id, name, format, ##__VA_ARGS__)
102-
#define O2_SIGNPOST_START(log, id, name, format, ...) os_signpost_interval_begin(private_o2_log_##log, id, name, format, ##__VA_ARGS__)
103-
#define O2_SIGNPOST_END(log, id, name, format, ...) os_signpost_interval_end(private_o2_log_##log, id, name, format, ##__VA_ARGS__)
104-
105-
#ifdef O2_SIGNPOST_IMPLEMENTATION
106-
/// We use a wrapper so that we can keep track of the logs.
107-
void* _o2_log_create(char const* name, char const* category)
108-
{
109-
// iterate over the list of logs and check if we already have
110-
// one with the same name.
111-
auto findLogByName = [](char const* name, void* log, void* context) -> bool {
112-
char const* currentName = (char const*)context;
113-
if (strcmp(name, currentName) == 0) {
114-
return false;
115-
}
116-
return true;
117-
};
118-
119-
o2_log_handle_t* handle = o2_walk_logs(findLogByName, (void*)name);
120-
121-
// If we found one, return it.
122-
if (handle) {
123-
return handle->log;
124-
}
125-
// Otherwise, create a new one and add it to the end of the list.
126-
os_log_t log = os_log_create(name, category);
127-
o2_log_handle_t* newHandle = new o2_log_handle_t();
128-
newHandle->log = log;
129-
newHandle->name = strdup(name);
130-
newHandle->next = o2_get_logs_tail().load();
131-
// Until I manage to replace the log I have in next, keep trying.
132-
// Notice this does not protect against two threads trying to insert
133-
// a log with the same name. I should probably do a sorted insert for that.
134-
while (!o2_get_logs_tail().compare_exchange_weak(newHandle->next, newHandle,
135-
std::memory_order_release,
136-
std::memory_order_relaxed)) {
137-
newHandle->next = o2_get_logs_tail();
138-
}
139-
140-
return log;
141-
}
95+
#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__)
96+
#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__)
97+
#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__)
98+
#define O2_SIGNPOST_ENABLED_MAC(log) os_signpost_enabled(private_o2_log_##log->os_log)
99+
#else
100+
// These are no-ops on linux.
101+
#define O2_DECLARE_LOG_MAC(x, category)
102+
#define O2_LOG_DEBUG_MAC(log, ...)
103+
#define O2_SIGNPOST_EVENT_EMIT_MAC(log, id, name, format, ...)
104+
#define O2_SIGNPOST_START_MAC(log, id, name, format, ...)
105+
#define O2_SIGNPOST_END_MAC(log, id, name, format, ...)
106+
#define O2_SIGNPOST_ENABLED_MAC(log) false
107+
#endif // __APPLE__
108+
109+
// Unless we are on apple we enable checking for signposts only if in debug mode or if we force them.
110+
#if defined(__APPLE__) || defined(O2_FORCE_SIGNPOSTS) || !defined(NDEBUG)
111+
#define O2_LOG_ENABLED(log) private_o2_log_##log->stacktrace
112+
#else
113+
#define O2_LOG_ENABLED(log) false
142114
#endif
143115

144-
#elif !defined(NDEBUG) || defined(O2_FORCE_LOGGER_SIGNPOST) || defined(O2_FORCE_SIGNPOSTS)
145-
146-
#ifndef O2_LOG_MACRO
147-
#if __has_include("Framework/Logger.h")
116+
#if !defined(O2_LOG_MACRO) && __has_include("Framework/Logger.h")
148117
#include "Framework/Logger.h"
149-
// If NDEBUG is not defined, we use the logger to print out the signposts at the debug level.
150-
#if !defined(NDEBUG)
151-
#define O2_LOG_MACRO(...) LOGF(debug, __VA_ARGS__)
152-
#elif defined(O2_FORCE_LOGGER_SIGNPOST) || defined(O2_FORCE_SIGNPOSTS)
153-
// 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.
154118
#define O2_LOG_MACRO(...) LOGF(info, __VA_ARGS__)
155-
#endif
156-
#else
119+
#elif !defined(O2_LOG_MACRO)
157120
// If we do not have the fairlogger, we simply print out the signposts to the console.
158121
// This is useful for things like the tests, which this way do not need to depend on the FairLogger.
159122
#define O2_LOG_MACRO(...) \
160123
do { \
161124
printf(__VA_ARGS__); \
162125
printf("\n"); \
163126
} while (0)
164-
#endif
165-
#endif
127+
#else
128+
#define O2_LOG_MACRO(...)
129+
#endif // O2_LOG_MACRO
166130

167131
// This is the linux implementation, it is not as nice as the apple one and simply prints out
168132
// the signpost information to the log.
@@ -181,7 +145,7 @@ struct _o2_lock_free_stack {
181145
// A log is simply an inbox which keeps track of the available id, so that we can print out different signposts
182146
// with different indentation levels.
183147
// supports up to 1024 paralle signposts before it spinlocks.
184-
typedef int _o2_signpost_index_t;
148+
using _o2_signpost_index_t = int;
185149

186150
struct _o2_activity_t {
187151
// How much the activity is indented in the output log.
@@ -191,10 +155,13 @@ struct _o2_activity_t {
191155

192156
struct _o2_signpost_id_t {
193157
// The id of the activity.
194-
int64_t id = -1;
158+
int64_t value = -1;
195159
};
196160

197161
struct _o2_log_t {
162+
#ifdef __APPLE__
163+
os_log_t os_log = nullptr;
164+
#endif
198165
// A circular buffer of available slots. Each unique interval pulls an id from this buffer.
199166
_o2_lock_free_stack slots;
200167
// Up to 256 activities can be active at the same time.
@@ -211,7 +178,10 @@ struct _o2_log_t {
211178
// 0 means the log is disabled.
212179
// 1 means only the current signpost is printed.
213180
// >1 means the current signpost and n levels of the stacktrace are printed.
214-
std::atomic<int> stacktrace = 1;
181+
std::atomic<int> stacktrace = 0;
182+
183+
// Default stacktrace level for the log, when enabled.
184+
int defaultStacktrace = 1;
215185
};
216186

217187
bool _o2_lock_free_stack_push(_o2_lock_free_stack& stack, const int& value, bool spin = false);
@@ -310,7 +280,7 @@ bool _o2_lock_free_stack_pop(_o2_lock_free_stack& stack, int& value, bool spin)
310280
}
311281
}
312282

313-
void* _o2_log_create(char const* name, int stacktrace)
283+
void* _o2_log_create(char const* name, int defaultStacktrace)
314284
{
315285
// iterate over the list of logs and check if we already have
316286
// one with the same name.
@@ -328,17 +298,26 @@ void* _o2_log_create(char const* name, int stacktrace)
328298
return handle->log;
329299
}
330300
// Otherwise, create a new one and add it to the end of the list.
331-
_o2_log_t* log = new _o2_log_t();
301+
auto* log = new _o2_log_t();
332302
// Write the initial 256 ids to the inbox, in reverse, so that the
333303
// linear search below is just for an handful of elements.
334304
int n = _o2_lock_free_stack::N;
335305
for (int i = 0; i < n; i++) {
336306
_o2_signpost_index_t signpost_index{n - 1 - i};
337307
_o2_lock_free_stack_push(log->slots, signpost_index, true);
338308
}
339-
log->stacktrace = stacktrace;
340-
o2_log_handle_t* newHandle = new o2_log_handle_t();
309+
log->defaultStacktrace = defaultStacktrace;
310+
auto* newHandle = new o2_log_handle_t();
341311
newHandle->log = log;
312+
#ifdef __APPLE__
313+
// On macOS, we use the os_signpost API so that when we are
314+
// using instruments we can see the messages there.
315+
if (defaultStacktrace > 1) {
316+
log->os_log = os_log_create(name, OS_LOG_CATEGORY_DYNAMIC_STACK_TRACING);
317+
} else {
318+
log->os_log = os_log_create(name, OS_LOG_CATEGORY_DYNAMIC_TRACING);
319+
}
320+
#endif
342321
newHandle->name = strdup(name);
343322
newHandle->next = o2_get_logs_tail().load();
344323
// Until I manage to replace the log I have in next, keep trying.
@@ -357,21 +336,17 @@ void* _o2_log_create(char const* name, int stacktrace)
357336
// If the slot is empty, it will return the id and increment the indentation level.
358337
void _o2_signpost_event_emit(_o2_log_t* log, _o2_signpost_id_t id, char const* name, char const* const format, ...)
359338
{
360-
// Nothing to be done
361-
if (log->stacktrace == 0) {
362-
return;
363-
}
364339
va_list args;
365340
va_start(args, format);
366341

367342
// Find the index of the activity
368343
int leading = 0;
369344

370345
// This is the equivalent of exclusive
371-
if (id.id != 0) {
346+
if (id.value != 0) {
372347
int i = 0;
373348
for (i = 0; i < log->ids.size(); ++i) {
374-
if (log->ids[i].id == id.id) {
349+
if (log->ids[i].value == id.value) {
375350
break;
376351
}
377352
}
@@ -385,7 +360,7 @@ void _o2_signpost_event_emit(_o2_log_t* log, _o2_signpost_id_t id, char const* n
385360
}
386361

387362
char prebuffer[4096];
388-
int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16s*>%*c", id.id, name, leading, ' ');
363+
int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16s*>%*c", id.value, name, leading, ' ');
389364
vsnprintf(prebuffer + s, 4096 - s, format, args);
390365
va_end(args);
391366
O2_LOG_MACRO("%s", prebuffer);
@@ -395,22 +370,19 @@ void _o2_signpost_event_emit(_o2_log_t* log, _o2_signpost_id_t id, char const* n
395370
// If the slot is empty, it will return the id and increment the indentation level.
396371
void _o2_signpost_interval_begin(_o2_log_t* log, _o2_signpost_id_t id, char const* name, char const* const format, ...)
397372
{
398-
if (log->stacktrace == 0) {
399-
return;
400-
}
401373
va_list args;
402374
va_start(args, format);
403375
// This is a unique slot for this interval.
404376
_o2_signpost_index_t signpost_index;
405377
_o2_lock_free_stack_pop(log->slots, signpost_index, true);
406378
// Put the id in the slot, to close things or to attach signposts to a given interval
407-
log->ids[signpost_index].id = id.id;
379+
log->ids[signpost_index].value = id.value;
408380
auto* activity = &log->activities[signpost_index];
409381
activity->indentation = log->current_indentation++;
410382
activity->name = name;
411383
int leading = activity->indentation * 2;
412384
char prebuffer[4096];
413-
int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16sS>%*c", id.id, name, leading, ' ');
385+
int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16sS>%*c", id.value, name, leading, ' ');
414386
vsnprintf(prebuffer + s, 4096 - s, format, args);
415387
va_end(args);
416388
O2_LOG_MACRO("%s", prebuffer);
@@ -424,7 +396,7 @@ void _o2_signpost_interval_end_v(_o2_log_t* log, _o2_signpost_id_t id, char cons
424396
// Find the index of the activity
425397
int i = 0;
426398
for (i = 0; i < log->ids.size(); ++i) {
427-
if (log->ids[i].id == id.id) {
399+
if (log->ids[i].value == id.value) {
428400
break;
429401
}
430402
}
@@ -439,13 +411,13 @@ void _o2_signpost_interval_end_v(_o2_log_t* log, _o2_signpost_id_t id, char cons
439411
_o2_activity_t* activity = &log->activities[i];
440412
int leading = activity->indentation * 2;
441413
char prebuffer[4096];
442-
int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16sE>%*c", id.id, name, leading, ' ');
414+
int s = snprintf(prebuffer, 4096, "id%.16" PRIx64 ":%-16sE>%*c", id.value, name, leading, ' ');
443415
vsnprintf(prebuffer + s, 4096 - s, format, args);
444416
O2_LOG_MACRO("%s", prebuffer);
445417
// Clear the slot
446418
activity->indentation = -1;
447419
activity->name = nullptr;
448-
log->ids[i].id = -1;
420+
log->ids[i].value = -1;
449421
// Put back the slot
450422
log->current_indentation--;
451423
_o2_signpost_index_t signpost_index{i};
@@ -468,29 +440,50 @@ void _o2_log_set_stacktrace(_o2_log_t* log, int stacktrace)
468440
}
469441
#endif // O2_SIGNPOST_IMPLEMENTATION
470442

471-
/// Dynamic logs need to be enabled via the O2_LOG_ENABLE_DYNAMIC macro. Notice this will only work
443+
#if defined(__APPLE__) || defined(O2_FORCE_SIGNPOSTS) || !defined(NDEBUG)
444+
/// Dynamic logs need to be enabled via the O2_LOG_ENABLE macro. Notice this will only work
472445
/// for the logger based logging, since the Apple version needs instruments to enable them.
473-
#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)
446+
#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)
474447
/// For the moment we do not support logs with a stacktrace.
475-
#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)
448+
#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)
476449
#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)
477-
#define O2_LOG_ENABLE_DYNAMIC(log) _o2_log_set_stacktrace(private_o2_log_##log, 1)
478-
// We print out only the first 64 frames.
479-
#define O2_LOG_ENABLE_STACKTRACE(log) _o2_log_set_stacktrace(private_o2_log_##log, 64)
450+
// When we enable the log, we set the stacktrace to the default value.
451+
#define O2_LOG_ENABLE(log) _o2_log_set_stacktrace(private_o2_log_##log, private_o2_log_##log->defaultStacktrace)
452+
#define O2_LOG_DISABLE(log) _o2_log_set_stacktrace(private_o2_log_##log, 0)
480453
// For the moment we simply use LOG DEBUG. We should have proper activities so that we can
481454
// turn on and off the printing.
482455
#define O2_LOG_DEBUG(log, ...) O2_LOG_MACRO(__VA_ARGS__)
483456
#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)
484457
#define O2_SIGNPOST_ID_GENERATE(name, log) _o2_signpost_id_t name = _o2_signpost_id_generate_local(private_o2_log_##log)
485-
#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__)
486-
#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__)
487-
#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__)
458+
// In case Instruments is attached, we switch to the Apple signpost API otherwise, both one
459+
// mac and on linux we use our own implementation, using the logger. We can use the same ids because
460+
// they are compatible between the two implementations, we also use remove_engineering_type to remove
461+
// the engineering types from the format string, so that we can use the same format string for both.
462+
#define O2_SIGNPOST_EVENT_EMIT(log, id, name, format, ...) __extension__({ \
463+
if (O2_SIGNPOST_ENABLED_MAC(log)) { \
464+
O2_SIGNPOST_EVENT_EMIT_MAC(log, id, name, format, ##__VA_ARGS__); \
465+
} else if (private_o2_log_##log->stacktrace) { \
466+
_o2_signpost_event_emit(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__); \
467+
} \
468+
})
469+
#define O2_SIGNPOST_START(log, id, name, format, ...) \
470+
if (O2_SIGNPOST_ENABLED_MAC(log)) { \
471+
O2_SIGNPOST_START_MAC(log, id, name, format, ##__VA_ARGS__); \
472+
} else if (private_o2_log_##log->stacktrace) { \
473+
_o2_signpost_interval_begin(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__); \
474+
}
475+
#define O2_SIGNPOST_END(log, id, name, format, ...) \
476+
if (O2_SIGNPOST_ENABLED_MAC(log)) { \
477+
O2_SIGNPOST_END_MAC(log, id, name, format, ##__VA_ARGS__); \
478+
} else if (private_o2_log_##log->stacktrace) { \
479+
_o2_signpost_interval_end(private_o2_log_##log, id, name, remove_engineering_type(format).data(), ##__VA_ARGS__); \
480+
}
488481
#else // This is the release implementation, it does nothing.
489482
#define O2_DECLARE_DYNAMIC_LOG(x)
490483
#define O2_DECLARE_DYNAMIC_STACKTRACE_LOG(x)
491484
#define O2_DECLARE_LOG(x, category)
492-
#define O2_LOG_ENABLE_DYNAMIC(log)
493-
#define O2_LOG_ENABLE_STACKTRACE(log)
485+
#define O2_LOG_ENABLE(log)
486+
#define O2_LOG_DISABLE(log)
494487
#define O2_LOG_DEBUG(log, ...)
495488
#define O2_SIGNPOST_ID_FROM_POINTER(name, log, pointer)
496489
#define O2_SIGNPOST_ID_GENERATE(name, log)

‎Framework/Foundation/test/test_Signpost.cxx‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,7 @@ int main(int argc, char** argv)
4343

4444
O2_SIGNPOST_START(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will not see, because they are off by default");
4545
O2_SIGNPOST_END(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will not see, because they are off by default");
46-
O2_LOG_ENABLE_DYNAMIC(test_SignpostDynamic);
46+
O2_LOG_ENABLE(test_SignpostDynamic);
4747
#ifdef __APPLE__
4848
// On Apple there is no way to turn on signposts in the logger, so we do not display this message
4949
O2_SIGNPOST_START(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will see, because we turned them on");

‎Framework/Foundation/test/test_SignpostLogger.cxx‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -51,7 +51,7 @@ int main(int argc, char** argv)
5151

5252
O2_SIGNPOST_START(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will not see, because they are off by default");
5353
O2_SIGNPOST_END(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will not see, because they are off by default");
54-
O2_LOG_ENABLE_DYNAMIC(test_SignpostDynamic);
54+
O2_LOG_ENABLE(test_SignpostDynamic);
5555
#ifdef __APPLE__
5656
// On Apple there is no way to turn on signposts in the logger, so we do not display this message
5757
O2_SIGNPOST_START(test_SignpostDynamic, id, "Test category", "This is dynamic signpost which you will see, because we turned them on");

0 commit comments

Comments
 (0)