Skip to content

Commit 2e9cd56

Browse files
author
Martin Pelikan
committedSep 28, 2017
[XRay] [compiler-rt] FDR logging arg1 handler
Summary: Write out records about logged function call first arguments. D32840 implements the reading of this in llvm-xray. Reviewers: dberris Subscribers: llvm-commits Differential Revision: https://reviews.llvm.org/D32844 llvm-svn: 314378
·
llvmorg-21-initllvmorg-6.0.0-rc1
1 parent 6571b3e commit 2e9cd56

File tree

8 files changed

+106
-71
lines changed

8 files changed

+106
-71
lines changed
 

‎compiler-rt/include/xray/xray_log_interface.h

+3
Original file line numberDiff line numberDiff line change
@@ -159,6 +159,9 @@ struct XRayLogImpl {
159159
/// always have a handler for function entry and exit events. In case the
160160
/// implementation wants to support arg1 (or other future extensions to XRay
161161
/// logging) those MUST be installed by the installed 'log_init' handler.
162+
///
163+
/// Because we didn't want to change the ABI of this struct, the arg1 handler
164+
/// may be silently overwritten during initialization as well.
162165
void (*handle_arg0)(int32_t, XRayEntryType);
163166

164167
/// The log implementation provided routine for when __xray_log_flushLog() is

‎compiler-rt/lib/xray/xray_fdr_log_records.h

+1
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,7 @@ struct alignas(16) MetadataRecord {
3030
TSCWrap,
3131
WalltimeMarker,
3232
CustomEventMarker,
33+
CallArgument,
3334
};
3435
// Use 7 bits to identify this record type.
3536
/* RecordKinds */ uint8_t RecordKind : 7;

‎compiler-rt/lib/xray/xray_fdr_logging.cc

+14-3
Original file line numberDiff line numberDiff line change
@@ -196,9 +196,17 @@ getTimestamp() XRAY_NEVER_INSTRUMENT {
196196
void fdrLoggingHandleArg0(int32_t FuncId,
197197
XRayEntryType Entry) XRAY_NEVER_INSTRUMENT {
198198
auto TSC_CPU = getTimestamp();
199-
__xray_fdr_internal::processFunctionHook(FuncId, Entry, std::get<0>(TSC_CPU),
200-
std::get<1>(TSC_CPU), clock_gettime,
201-
LoggingStatus, *BQ);
199+
__xray_fdr_internal::processFunctionHook(
200+
FuncId, Entry, std::get<0>(TSC_CPU), std::get<1>(TSC_CPU), 0,
201+
clock_gettime, *BQ);
202+
}
203+
204+
void fdrLoggingHandleArg1(int32_t FuncId, XRayEntryType Entry,
205+
uint64_t Arg) XRAY_NEVER_INSTRUMENT {
206+
auto TSC_CPU = getTimestamp();
207+
__xray_fdr_internal::processFunctionHook(
208+
FuncId, Entry, std::get<0>(TSC_CPU), std::get<1>(TSC_CPU), Arg,
209+
clock_gettime, *BQ);
202210
}
203211

204212
void fdrLoggingHandleCustomEvent(void *Event,
@@ -280,6 +288,9 @@ XRayLogInitStatus fdrLoggingInit(std::size_t BufferSize, std::size_t BufferMax,
280288
return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
281289
}
282290

291+
// Arg1 handler should go in first to avoid concurrent code accidentally
292+
// falling back to arg0 when it should have ran arg1.
293+
__xray_set_handler_arg1(fdrLoggingHandleArg1);
283294
// Install the actual handleArg0 handler after initialising the buffers.
284295
__xray_set_handler(fdrLoggingHandleArg0);
285296
__xray_set_customevent_handler(fdrLoggingHandleCustomEvent);

‎compiler-rt/lib/xray/xray_fdr_logging.h

+1
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,7 @@ XRayLogInitStatus fdrLoggingInit(size_t BufferSize, size_t BufferMax,
3030
void *Options, size_t OptionsSize);
3131
XRayLogInitStatus fdrLoggingFinalize();
3232
void fdrLoggingHandleArg0(int32_t FuncId, XRayEntryType Entry);
33+
void fdrLoggingHandleArg1(int32_t FuncId, XRayEntryType Entry, uint64_t Arg1);
3334
XRayLogFlushStatus fdrLoggingFlush();
3435
XRayLogInitStatus fdrLoggingReset();
3536

‎compiler-rt/lib/xray/xray_fdr_logging_impl.h

+69-61
Original file line numberDiff line numberDiff line change
@@ -91,19 +91,6 @@ static void writeEOBMetadata();
9191
/// TSC Wrap records are written when a TSC delta encoding scheme overflows.
9292
static void writeTSCWrapMetadata(uint64_t TSC);
9393

94-
/// Here's where the meat of the processing happens. The writer captures
95-
/// function entry, exit and tail exit points with a time and will create
96-
/// TSCWrap, NewCPUId and Function records as necessary. The writer might
97-
/// walk backward through its buffer and erase trivial functions to avoid
98-
/// polluting the log and may use the buffer queue to obtain or release a
99-
/// buffer.
100-
static void processFunctionHook(int32_t FuncId, XRayEntryType Entry,
101-
uint64_t TSC, unsigned char CPU,
102-
int (*wall_clock_reader)(clockid_t,
103-
struct timespec *),
104-
__sanitizer::atomic_sint32_t &LoggingStatus,
105-
const std::shared_ptr<BufferQueue> &BQ);
106-
10794
// Group together thread-local-data in a struct, then hide it behind a function
10895
// call so that it can be initialized on first use instead of as a global.
10996
struct ThreadLocalData {
@@ -331,9 +318,22 @@ inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT {
331318
writeTSCWrapMetadata(TSC, getThreadLocalData().RecordPtr);
332319
}
333320

334-
inline void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
335-
XRayEntryType EntryType,
336-
char *&MemPtr) XRAY_NEVER_INSTRUMENT {
321+
// Call Argument metadata records store the arguments to a function in the
322+
// order of their appearance; holes are not supported by the buffer format.
323+
static inline void writeCallArgumentMetadata(uint64_t A) XRAY_NEVER_INSTRUMENT {
324+
auto &TLD = getThreadLocalData();
325+
MetadataRecord CallArg;
326+
CallArg.Type = uint8_t(RecordType::Metadata);
327+
CallArg.RecordKind = uint8_t(MetadataRecord::RecordKinds::CallArgument);
328+
329+
std::memcpy(CallArg.Data, &A, sizeof(A));
330+
std::memcpy(TLD.RecordPtr, &CallArg, sizeof(MetadataRecord));
331+
TLD.RecordPtr += sizeof(MetadataRecord);
332+
}
333+
334+
static inline void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
335+
XRayEntryType EntryType,
336+
char *&MemPtr) XRAY_NEVER_INSTRUMENT {
337337
std::aligned_storage<sizeof(FunctionRecord), alignof(FunctionRecord)>::type
338338
AlignedFuncRecordBuffer;
339339
auto &FuncRecord =
@@ -560,6 +560,41 @@ inline bool isLogInitializedAndReady(
560560
return true;
561561
} // namespace __xray_fdr_internal
562562

563+
// Compute the TSC difference between the time of measurement and the previous
564+
// event. There are a few interesting situations we need to account for:
565+
//
566+
// - The thread has migrated to a different CPU. If this is the case, then
567+
// we write down the following records:
568+
//
569+
// 1. A 'NewCPUId' Metadata record.
570+
// 2. A FunctionRecord with a 0 for the TSCDelta field.
571+
//
572+
// - The TSC delta is greater than the 32 bits we can store in a
573+
// FunctionRecord. In this case we write down the following records:
574+
//
575+
// 1. A 'TSCWrap' Metadata record.
576+
// 2. A FunctionRecord with a 0 for the TSCDelta field.
577+
//
578+
// - The TSC delta is representable within the 32 bits we can store in a
579+
// FunctionRecord. In this case we write down just a FunctionRecord with
580+
// the correct TSC delta.
581+
inline uint32_t writeCurrentCPUTSC(ThreadLocalData &TLD, uint64_t TSC, uint8_t CPU) {
582+
if (CPU != TLD.CurrentCPU) {
583+
// We've moved to a new CPU.
584+
writeNewCPUIdMetadata(CPU, TSC);
585+
return 0;
586+
}
587+
// If the delta is greater than the range for a uint32_t, then we write out
588+
// the TSC wrap metadata entry with the full TSC, and the TSC for the
589+
// function record be 0.
590+
uint64_t Delta = TSC - TLD.LastTSC;
591+
if (Delta <= std::numeric_limits<uint32_t>::max())
592+
return Delta;
593+
594+
writeTSCWrapMetadata(TSC);
595+
return 0;
596+
}
597+
563598
inline void endBufferIfFull() XRAY_NEVER_INSTRUMENT {
564599
auto &TLD = getThreadLocalData();
565600
auto BufferStart = static_cast<char *>(TLD.Buffer.Buffer);
@@ -573,10 +608,15 @@ inline void endBufferIfFull() XRAY_NEVER_INSTRUMENT {
573608

574609
thread_local volatile bool Running = false;
575610

611+
/// Here's where the meat of the processing happens. The writer captures
612+
/// function entry, exit and tail exit points with a time and will create
613+
/// TSCWrap, NewCPUId and Function records as necessary. The writer might
614+
/// walk backward through its buffer and erase trivial functions to avoid
615+
/// polluting the log and may use the buffer queue to obtain or release a
616+
/// buffer.
576617
inline void processFunctionHook(
577618
int32_t FuncId, XRayEntryType Entry, uint64_t TSC, unsigned char CPU,
578-
int (*wall_clock_reader)(clockid_t, struct timespec *),
579-
__sanitizer::atomic_sint32_t &LoggingStatus,
619+
uint64_t Arg1, int (*wall_clock_reader)(clockid_t, struct timespec *),
580620
const std::shared_ptr<BufferQueue> &BQ) XRAY_NEVER_INSTRUMENT {
581621
// Prevent signal handler recursion, so in case we're already in a log writing
582622
// mode and the signal handler comes in (and is also instrumented) then we
@@ -609,10 +649,10 @@ inline void processFunctionHook(
609649
// - The least number of bytes we will ever write is 8
610650
// (sizeof(FunctionRecord)) only if the delta between the previous entry
611651
// and this entry is within 32 bits.
612-
// - The most number of bytes we will ever write is 8 + 16 = 24. This is
613-
// computed by:
652+
// - The most number of bytes we will ever write is 8 + 16 + 16 = 40.
653+
// This is computed by:
614654
//
615-
// sizeof(FunctionRecord) + sizeof(MetadataRecord)
655+
// MaxSize = sizeof(FunctionRecord) + 2 * sizeof(MetadataRecord)
616656
//
617657
// These arise in the following cases:
618658
//
@@ -626,6 +666,7 @@ inline void processFunctionHook(
626666
// FunctionRecord.
627667
// 3. When we learn about a new CPU ID, we need to write down a "new cpu
628668
// id" MetadataRecord before writing out the actual FunctionRecord.
669+
// 4. The second MetadataRecord is the optional function call argument.
629670
//
630671
// - An End-of-Buffer (EOB) MetadataRecord is 16 bytes.
631672
//
@@ -634,53 +675,18 @@ inline void processFunctionHook(
634675
// MetadataRecord. If we don't have enough space after writing as much as 24
635676
// bytes in the end of the buffer, we need to write out the EOB, get a new
636677
// Buffer, set it up properly before doing any further writing.
637-
//
638-
if (!prepareBuffer(wall_clock_reader, FunctionRecSize + MetadataRecSize)) {
678+
size_t MaxSize = FunctionRecSize + 2 * MetadataRecSize;
679+
if (!prepareBuffer(wall_clock_reader, MaxSize)) {
639680
TLD.LocalBQ = nullptr;
640681
return;
641682
}
642683

643-
// By this point, we are now ready to write at most 24 bytes (one metadata
644-
// record and one function record).
645-
assert((TLD.RecordPtr + (MetadataRecSize + FunctionRecSize)) -
646-
static_cast<char *>(TLD.Buffer.Buffer) >=
684+
// By this point, we are now ready to write up to 40 bytes (explained above).
685+
assert((TLD.RecordPtr + MaxSize) - static_cast<char *>(TLD.Buffer.Buffer) >=
647686
static_cast<ptrdiff_t>(MetadataRecSize) &&
648687
"Misconfigured BufferQueue provided; Buffer size not large enough.");
649688

650-
// Here we compute the TSC Delta. There are a few interesting situations we
651-
// need to account for:
652-
//
653-
// - The thread has migrated to a different CPU. If this is the case, then
654-
// we write down the following records:
655-
//
656-
// 1. A 'NewCPUId' Metadata record.
657-
// 2. A FunctionRecord with a 0 for the TSCDelta field.
658-
//
659-
// - The TSC delta is greater than the 32 bits we can store in a
660-
// FunctionRecord. In this case we write down the following records:
661-
//
662-
// 1. A 'TSCWrap' Metadata record.
663-
// 2. A FunctionRecord with a 0 for the TSCDelta field.
664-
//
665-
// - The TSC delta is representable within the 32 bits we can store in a
666-
// FunctionRecord. In this case we write down just a FunctionRecord with
667-
// the correct TSC delta.
668-
//
669-
uint32_t RecordTSCDelta = 0;
670-
if (CPU != TLD.CurrentCPU) {
671-
// We've moved to a new CPU.
672-
writeNewCPUIdMetadata(CPU, TSC);
673-
} else {
674-
// If the delta is greater than the range for a uint32_t, then we write out
675-
// the TSC wrap metadata entry with the full TSC, and the TSC for the
676-
// function record be 0.
677-
auto Delta = TSC - TLD.LastTSC;
678-
if (Delta > (1ULL << 32) - 1)
679-
writeTSCWrapMetadata(TSC);
680-
else
681-
RecordTSCDelta = Delta;
682-
}
683-
689+
auto RecordTSCDelta = writeCurrentCPUTSC(TLD, TSC, CPU);
684690
TLD.LastTSC = TSC;
685691
TLD.CurrentCPU = CPU;
686692
switch (Entry) {
@@ -711,6 +717,8 @@ inline void processFunctionHook(
711717
}
712718

713719
writeFunctionRecord(FuncId, RecordTSCDelta, Entry, TLD.RecordPtr);
720+
if (Entry == XRayEntryType::LOG_ARGS_ENTRY)
721+
writeCallArgumentMetadata(Arg1);
714722

715723
// If we've exhausted the buffer by this time, we then release the buffer to
716724
// make sure that other threads may start using this buffer.

‎compiler-rt/lib/xray/xray_trampoline_x86_64.S

+3-3
Original file line numberDiff line numberDiff line change
@@ -173,11 +173,11 @@ __xray_ArgLoggerEntry:
173173

174174
.Larg1entryLog:
175175

176-
// First argument will become the third
176+
// First argument will become the third
177177
movq %rdi, %rdx
178178

179-
// XRayEntryType::ENTRY into the second
180-
xorq %rsi, %rsi
179+
// XRayEntryType::LOG_ARGS_ENTRY into the second
180+
mov $0x3, %esi
181181

182182
// 32-bit function ID becomes the first
183183
movl %r10d, %edi

‎compiler-rt/test/xray/TestCases/Linux/arg1-logger.cc

+3-3
Original file line numberDiff line numberDiff line change
@@ -29,15 +29,15 @@ int main() {
2929

3030
__xray_set_handler_arg1(arg1logger);
3131
foo(nullptr);
32-
// CHECK: Arg1: 0, XRayEntryType 0
32+
// CHECK: Arg1: 0, XRayEntryType 3
3333

3434
__xray_remove_handler_arg1();
3535
foo((void *) 0xBADC0DE);
3636
// nothing expected to see here
3737

3838
__xray_set_handler_arg1(arg1logger);
3939
foo((void *) 0xDEADBEEFCAFE);
40-
// CHECK-NEXT: Arg1: deadbeefcafe, XRayEntryType 0
40+
// CHECK-NEXT: Arg1: deadbeefcafe, XRayEntryType 3
4141
foo((void *) -1);
42-
// CHECK-NEXT: Arg1: ffffffffffffffff, XRayEntryType 0
42+
// CHECK-NEXT: Arg1: ffffffffffffffff, XRayEntryType 3
4343
}

‎compiler-rt/test/xray/TestCases/Linux/fdr-mode.cc

+12-1
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,9 @@ thread_local uint64_t var = 0;
3030

3131
[[clang::xray_always_instrument]] void __attribute__((noinline)) fA() { fB(); }
3232

33+
[[clang::xray_always_instrument, clang::xray_log_args(1)]]
34+
void __attribute__((noinline)) fArg(int) { }
35+
3336
int main(int argc, char *argv[]) {
3437
using namespace __xray;
3538
FDRLoggingOptions Options;
@@ -52,6 +55,7 @@ int main(int argc, char *argv[]) {
5255
fC();
5356
fB();
5457
fA();
58+
fArg(1);
5559
});
5660
other_thread.join();
5761
std::cout << "Joined" << std::endl;
@@ -85,8 +89,15 @@ int main(int argc, char *argv[]) {
8589
// TRACE-DAG: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
8690
// TRACE: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }
8791

92+
// TRACE-DAG: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2]], kind: function-enter-arg, tsc: {{[0-9]+}} }
93+
// TRACE-DAG: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
94+
8895
// Assert that when unwriting is enabled with a high threshold time, all the function records are erased. A CPU switch could erroneously fail this test, but
8996
// is unlikely given the test program.
90-
// UNWRITE: header
97+
// Even with a high threshold, arg1 logging is never unwritten.
98+
// UNWRITE: header:
99+
// UNWRITE: records:
100+
// UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter-arg, tsc: {{[0-9]+}} }
101+
// UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
91102
// UNWRITE-NOT: function-enter
92103
// UNWRITE-NOT: function-{{exit|tail-exit}}

0 commit comments

Comments
 (0)
Please sign in to comment.