/home/travis/build/MoarVM/MoarVM/src/profiler/telemeh.c

Source (jump to first uncovered line)
#include <moar.h>

#ifdef HAVE_TELEMEH

#include <stdio.h>
#include <time.h>
#include <string.h>

#if MVM_RDTSCP
# ifdef _WIN32
#  include <intrin.h>
# else
#  if defined(__x86_64__) || defined(__i386__)
#   include <x86intrin.h>
#  else
unsigned int __rdtscp(unsigned int *inval) {
    *inval = 0;
    return 0;
}
#  endif
# endif
#else
unsigned int __rdtscp(unsigned int *inval) {
    *inval = 0;
    return 0;
}
#endif

double ticksPerSecond;

// use RDTSCP instruction to get the required pipeline flush implicitly
#define READ_TSC(tscValue) \
{ \
    unsigned int _tsc_aux; \
    tscValue = __rdtscp(&_tsc_aux); \
}

#ifdef __clang__
#if !__has_builtin(__builtin_ia32_rdtscp)
#undef READ_TSC
#define READ_TSC(tscValue) { tscValue = 0; }
#warning "not using rdtscp"
#endif
#endif

#ifdef _WIN32
#include <windows.h>
#define MVM_sleep(ms) do { Sleep(ms); } while (0)
#else
#include <unistd.h>
#define MVM_sleep(ms) do { usleep(ms * 1000); } while (0)
#endif

enum RecordType {
    Calibration,
    Epoch,
    TimeStamp,
    IntervalStart,
    IntervalEnd,
    IntervalAnnotation,
    DynamicString
};

struct CalibrationRecord {
    double ticksPerSecond;
};

struct EpochRecord {
    unsigned long long time;
};

struct TimeStampRecord {
    unsigned long long time;
    const char *description;
};

struct IntervalRecord {
    unsigned long long time;
    unsigned int intervalID;
    const char *description;
};

struct IntervalAnnotation {
    unsigned int intervalID;
    const char *description;
};

struct DynamicString {
    unsigned int intervalID;
    char *description;
};

struct TelemetryRecord {
    enum RecordType recordType;

    uintptr_t threadID;

    union {
        struct CalibrationRecord calibration;
        struct EpochRecord epoch;
        struct TimeStampRecord timeStamp;
        struct IntervalRecord interval;
        struct IntervalAnnotation annotation;
        struct DynamicString annotation_dynamic;
    } u;
};

#define RECORD_BUFFER_SIZE 10000

// this is a ring buffer of telemetry events
static struct TelemetryRecord recordBuffer[RECORD_BUFFER_SIZE];
static AO_t recordBufferIndex = 0;
static unsigned int lastSerializedIndex = 0;
static unsigned long long beginningEpoch = 0;
static unsigned int telemetry_active = 0;

struct TelemetryRecord *newRecord()
{
    AO_t newBufferIndex, recordIndex;
    struct TelemetryRecord *record;

    do {
        recordIndex = MVM_load(&recordBufferIndex);
        newBufferIndex = (recordBufferIndex + 1) % RECORD_BUFFER_SIZE;
    } while(!MVM_trycas(&recordBufferIndex, recordIndex, newBufferIndex));

    record = &recordBuffer[recordIndex];
    return record;
}

static unsigned int intervalIDCounter = 0;

MVM_PUBLIC void MVM_telemetry_timestamp(MVMThreadContext *threadID, const char *description)
{
    struct TelemetryRecord *record;

    if (!telemetry_active) { return; }

    record = newRecord();

    READ_TSC(record->u.timeStamp.time);
    record->recordType = TimeStamp;
    record->threadID = (uintptr_t)threadID;
    record->u.timeStamp.description = description;
}

MVM_PUBLIC unsigned int MVM_telemetry_interval_start(MVMThreadContext *threadID, const char *description)
{
    struct TelemetryRecord *record;

    unsigned int intervalID;

    if (!telemetry_active) { return 0; }

    record = newRecord();
    MVM_incr(&intervalIDCounter);
    intervalID = MVM_load(&intervalIDCounter);
    READ_TSC(record->u.interval.time);

    record->recordType = IntervalStart;
    record->threadID = (uintptr_t)threadID;
    record->u.interval.intervalID = intervalID;
    record->u.interval.description = description;

    return intervalID;
}

MVM_PUBLIC void MVM_telemetry_interval_stop(MVMThreadContext *threadID, int intervalID, const char *description)
{
    struct TelemetryRecord *record;

    if (!telemetry_active) { return; }

    record = newRecord();
    READ_TSC(record->u.interval.time);

    record->recordType = IntervalEnd;
    record->threadID = (uintptr_t)threadID;
    record->u.interval.intervalID = intervalID;
    record->u.interval.description = description;
}

MVM_PUBLIC void MVM_telemetry_interval_annotate(uintptr_t subject, int intervalID, const char *description) {
    struct TelemetryRecord *record;

    if (!telemetry_active) { return; }

    record = newRecord();
    record->recordType = IntervalAnnotation;
    record->threadID = subject;
    record->u.annotation.intervalID = intervalID;
    record->u.annotation.description = description;
}

MVM_PUBLIC void MVM_telemetry_interval_annotate_dynamic(uintptr_t subject, int intervalID, char *description) {
    struct TelemetryRecord *record = NULL;
    char *temp = NULL;
    size_t temp_size;

    if (!telemetry_active) { return; }
    temp_size = strlen(description) + 1;
    temp      = malloc(temp_size);
    strncpy(temp, description, temp_size);

    record = newRecord();
    record->recordType = DynamicString;
    record->threadID = subject;
    record->u.annotation_dynamic.intervalID = intervalID;
    record->u.annotation_dynamic.description = temp;
}

void calibrateTSC(FILE *outfile)
{
    unsigned long long startTsc, endTsc;
    uint64_t startTime, endTime;

    startTime = uv_hrtime();
    READ_TSC(startTsc)

    MVM_sleep(1000);

    endTime = uv_hrtime();
    READ_TSC(endTsc)

    {
        unsigned long long ticks = endTsc - startTsc;

        unsigned long long wallClockTime = endTime - startTime;

        ticksPerSecond = (double)ticks / (double)wallClockTime;
        ticksPerSecond *= 1000000000.0;
    }
}

static uv_thread_t backgroundSerializationThread;
static volatile int continueBackgroundSerialization = 1;

void serializeTelemetryBufferRange(FILE *outfile, unsigned int serializationStart, unsigned int serializationEnd)
{
    unsigned int i;
    for(i = serializationStart; i < serializationEnd; i++) {
        struct TelemetryRecord *record = &recordBuffer[i];

        fprintf(outfile, "%10" PRIxPTR " ", record->threadID);

        switch(record->recordType) {
            case Calibration:
                fprintf(outfile, "Calibration: %f ticks per second\n", record->u.calibration.ticksPerSecond);
                break;
            case Epoch:
                fprintf(outfile, "Epoch counter: %lld\n", record->u.epoch.time);
                break;
            case TimeStamp:
                fprintf(outfile, "%15lld -|-  \"%s\"\n", record->u.timeStamp.time - beginningEpoch, record->u.timeStamp.description);
                break;
            case IntervalStart:
                fprintf(outfile, "%15lld (-   \"%s\" (%d)\n", record->u.interval.time - beginningEpoch, record->u.interval.description, record->u.interval.intervalID);
                break;
            case IntervalEnd:
                fprintf(outfile, "%15lld  -)  \"%s\" (%d)\n", record->u.interval.time - beginningEpoch, record->u.interval.description, record->u.interval.intervalID);
                break;
            case IntervalAnnotation:
                fprintf(outfile,  "%15s ???  \"%s\" (%d)\n", " ", record->u.annotation.description, record->u.annotation.intervalID);
                break;
            case DynamicString:
                fprintf(outfile,  "%15s ???  \"%s\" (%d)\n", " ", record->u.annotation_dynamic.description, record->u.annotation_dynamic.intervalID);
                free(record->u.annotation_dynamic.description);
                break;
        }
    }
}

void serializeTelemetryBuffer(FILE *outfile)
{
    unsigned int serializationEnd = recordBufferIndex;
    unsigned int serializationStart = lastSerializedIndex;

    if(serializationEnd < serializationStart) {
        serializeTelemetryBufferRange(outfile, serializationStart, RECORD_BUFFER_SIZE);
        serializeTelemetryBufferRange(outfile, 0, serializationEnd);
    } else {
        serializeTelemetryBufferRange(outfile, serializationStart, serializationEnd);
    }

    lastSerializedIndex = serializationEnd;
}

void *backgroundSerialization(void *outfile)
{
    while(continueBackgroundSerialization) {
        MVM_sleep(500);
        serializeTelemetryBuffer((FILE *)outfile);
    }

    fclose((FILE *)outfile);

    return NULL;
}

MVM_PUBLIC void MVM_telemetry_init(FILE *outfile)
{
    struct TelemetryRecord *calibrationRecord;
    struct TelemetryRecord *epochRecord;
    int threadCreateError;

    telemetry_active = 1;

    calibrateTSC(outfile);

    calibrationRecord = newRecord();
    calibrationRecord->u.calibration.ticksPerSecond = ticksPerSecond;
    calibrationRecord->recordType = Calibration;

    epochRecord = newRecord();
    READ_TSC(epochRecord->u.epoch.time)
    epochRecord->recordType = Epoch;

    beginningEpoch = epochRecord->u.epoch.time;

    threadCreateError = uv_thread_create(&backgroundSerializationThread, (uv_thread_cb)backgroundSerialization, (void *)outfile);
    if (threadCreateError != 0)  {
        telemetry_active = 0;

        fprintf(stderr, "MoarVM: Could not initialize telemetry: %s\n", uv_strerror(threadCreateError));
    }
}

MVM_PUBLIC void MVM_telemetry_finish()
{
    continueBackgroundSerialization = 0;
    uv_thread_join(&backgroundSerializationThread);
}

#else

MVM_PUBLIC void MVM_telemetry_timestamp(MVMThreadContext *threadID, const char *description) { }

MVM_PUBLIC unsigned int MVM_telemetry_interval_start(MVMThreadContext *threadID, const char *description) { return 0; }
MVM_PUBLIC void MVM_telemetry_interval_stop(MVMThreadContext *threadID, int intervalID, const char *description) { }
MVM_PUBLIC void MVM_telemetry_interval_annotate(uintptr_t subject, int intervalID, const char *description) { }
MVM_PUBLIC void MVM_telemetry_interval_annotate_dynamic(uintptr_t subject, int intervalID, char *description) { }

MVM_PUBLIC void MVM_telemetry_init(FILE *outfile) { }
MVM_PUBLIC void MVM_telemetry_finish() { }

#endif

Coverage Report

Created: 2018-07-03 15:31

Line	Count	Source (jump to first uncovered line)
1		#include <moar.h>
2
3		#ifdef HAVE_TELEMEH
4
5		#include <stdio.h>
6		#include <time.h>
7		#include <string.h>
8
9		#if MVM_RDTSCP
10		# ifdef _WIN32
11		# include <intrin.h>
12		# else
13		# if defined(__x86_64__) \|\| defined(__i386__)
14		# include <x86intrin.h>
15		# else
16		unsigned int __rdtscp(unsigned int *inval) {
17		*inval = 0;
18		return 0;
19		}
20		# endif
21		# endif
22		#else
23		unsigned int __rdtscp(unsigned int *inval) {
24		*inval = 0;
25		return 0;
26		}
27		#endif
28
29		double ticksPerSecond;
30
31		// use RDTSCP instruction to get the required pipeline flush implicitly
32		#define READ_TSC(tscValue) \
33		{ \
34		unsigned int _tsc_aux; \
35		tscValue = __rdtscp(&_tsc_aux); \
36		}
37
38		#ifdef __clang__
39		#if !__has_builtin(__builtin_ia32_rdtscp)
40		#undef READ_TSC
41		#define READ_TSC(tscValue) { tscValue = 0; }
42		#warning "not using rdtscp"
43		#endif
44		#endif
45
46		#ifdef _WIN32
47		#include <windows.h>
48		#define MVM_sleep(ms) do { Sleep(ms); } while (0)
49		#else
50		#include <unistd.h>
51		#define MVM_sleep(ms) do { usleep(ms * 1000); } while (0)
52		#endif
53
54		enum RecordType {
55		Calibration,
56		Epoch,
57		TimeStamp,
58		IntervalStart,
59		IntervalEnd,
60		IntervalAnnotation,
61		DynamicString
62		};
63
64		struct CalibrationRecord {
65		double ticksPerSecond;
66		};
67
68		struct EpochRecord {
69		unsigned long long time;
70		};
71
72		struct TimeStampRecord {
73		unsigned long long time;
74		const char *description;
75		};
76
77		struct IntervalRecord {
78		unsigned long long time;
79		unsigned int intervalID;
80		const char *description;
81		};
82
83		struct IntervalAnnotation {
84		unsigned int intervalID;
85		const char *description;
86		};
87
88		struct DynamicString {
89		unsigned int intervalID;
90		char *description;
91		};
92
93		struct TelemetryRecord {
94		enum RecordType recordType;
95
96		uintptr_t threadID;
97
98		union {
99		struct CalibrationRecord calibration;
100		struct EpochRecord epoch;
101		struct TimeStampRecord timeStamp;
102		struct IntervalRecord interval;
103		struct IntervalAnnotation annotation;
104		struct DynamicString annotation_dynamic;
105		} u;
106		};
107
108		#define RECORD_BUFFER_SIZE 10000
109
110		// this is a ring buffer of telemetry events
111		static struct TelemetryRecord recordBuffer[RECORD_BUFFER_SIZE];
112		static AO_t recordBufferIndex = 0;
113		static unsigned int lastSerializedIndex = 0;
114		static unsigned long long beginningEpoch = 0;
115		static unsigned int telemetry_active = 0;
116
117		struct TelemetryRecord *newRecord()
118		{
119		AO_t newBufferIndex, recordIndex;
120		struct TelemetryRecord *record;
121
122		do {
123		recordIndex = MVM_load(&recordBufferIndex);
124		newBufferIndex = (recordBufferIndex + 1) % RECORD_BUFFER_SIZE;
125		} while(!MVM_trycas(&recordBufferIndex, recordIndex, newBufferIndex));
126
127		record = &recordBuffer[recordIndex];
128		return record;
129		}
130
131		static unsigned int intervalIDCounter = 0;
132
133		MVM_PUBLIC void MVM_telemetry_timestamp(MVMThreadContext threadID, const char description)
134		{
135		struct TelemetryRecord *record;
136
137		if (!telemetry_active) { return; }
138
139		record = newRecord();
140
141		READ_TSC(record->u.timeStamp.time);
142		record->recordType = TimeStamp;
143		record->threadID = (uintptr_t)threadID;
144		record->u.timeStamp.description = description;
145		}
146
147		MVM_PUBLIC unsigned int MVM_telemetry_interval_start(MVMThreadContext threadID, const char description)
148		{
149		struct TelemetryRecord *record;
150
151		unsigned int intervalID;
152
153		if (!telemetry_active) { return 0; }
154
155		record = newRecord();
156		MVM_incr(&intervalIDCounter);
157		intervalID = MVM_load(&intervalIDCounter);
158		READ_TSC(record->u.interval.time);
159
160		record->recordType = IntervalStart;
161		record->threadID = (uintptr_t)threadID;
162		record->u.interval.intervalID = intervalID;
163		record->u.interval.description = description;
164
165		return intervalID;
166		}
167
168		MVM_PUBLIC void MVM_telemetry_interval_stop(MVMThreadContext threadID, int intervalID, const char description)
169		{
170		struct TelemetryRecord *record;
171
172		if (!telemetry_active) { return; }
173
174		record = newRecord();
175		READ_TSC(record->u.interval.time);
176
177		record->recordType = IntervalEnd;
178		record->threadID = (uintptr_t)threadID;
179		record->u.interval.intervalID = intervalID;
180		record->u.interval.description = description;
181		}
182
183		MVM_PUBLIC void MVM_telemetry_interval_annotate(uintptr_t subject, int intervalID, const char *description) {
184		struct TelemetryRecord *record;
185
186		if (!telemetry_active) { return; }
187
188		record = newRecord();
189		record->recordType = IntervalAnnotation;
190		record->threadID = subject;
191		record->u.annotation.intervalID = intervalID;
192		record->u.annotation.description = description;
193		}
194
195		MVM_PUBLIC void MVM_telemetry_interval_annotate_dynamic(uintptr_t subject, int intervalID, char *description) {
196		struct TelemetryRecord *record = NULL;
197		char *temp = NULL;
198		size_t temp_size;
199
200		if (!telemetry_active) { return; }
201		temp_size = strlen(description) + 1;
202		temp = malloc(temp_size);
203		strncpy(temp, description, temp_size);
204
205		record = newRecord();
206		record->recordType = DynamicString;
207		record->threadID = subject;
208		record->u.annotation_dynamic.intervalID = intervalID;
209		record->u.annotation_dynamic.description = temp;
210		}
211
212		void calibrateTSC(FILE *outfile)
213		{
214		unsigned long long startTsc, endTsc;
215		uint64_t startTime, endTime;
216
217		startTime = uv_hrtime();
218		READ_TSC(startTsc)
219
220		MVM_sleep(1000);
221
222		endTime = uv_hrtime();
223		READ_TSC(endTsc)
224
225		{
226		unsigned long long ticks = endTsc - startTsc;
227
228		unsigned long long wallClockTime = endTime - startTime;
229
230		ticksPerSecond = (double)ticks / (double)wallClockTime;
231		ticksPerSecond *= 1000000000.0;
232		}
233		}
234
235		static uv_thread_t backgroundSerializationThread;
236		static volatile int continueBackgroundSerialization = 1;
237
238		void serializeTelemetryBufferRange(FILE *outfile, unsigned int serializationStart, unsigned int serializationEnd)
239		{
240		unsigned int i;
241		for(i = serializationStart; i < serializationEnd; i++) {
242		struct TelemetryRecord *record = &recordBuffer[i];
243
244		fprintf(outfile, "%10" PRIxPTR " ", record->threadID);
245
246		switch(record->recordType) {
247		case Calibration:
248		fprintf(outfile, "Calibration: %f ticks per second\n", record->u.calibration.ticksPerSecond);
249		break;
250		case Epoch:
251		fprintf(outfile, "Epoch counter: %lld\n", record->u.epoch.time);
252		break;
253		case TimeStamp:
254		fprintf(outfile, "%15lld -\|- \"%s\"\n", record->u.timeStamp.time - beginningEpoch, record->u.timeStamp.description);
255		break;
256		case IntervalStart:
257		fprintf(outfile, "%15lld (- \"%s\" (%d)\n", record->u.interval.time - beginningEpoch, record->u.interval.description, record->u.interval.intervalID);
258		break;
259		case IntervalEnd:
260		fprintf(outfile, "%15lld -) \"%s\" (%d)\n", record->u.interval.time - beginningEpoch, record->u.interval.description, record->u.interval.intervalID);
261		break;
262		case IntervalAnnotation:
263		fprintf(outfile, "%15s ??? \"%s\" (%d)\n", " ", record->u.annotation.description, record->u.annotation.intervalID);
264		break;
265		case DynamicString:
266		fprintf(outfile, "%15s ??? \"%s\" (%d)\n", " ", record->u.annotation_dynamic.description, record->u.annotation_dynamic.intervalID);
267		free(record->u.annotation_dynamic.description);
268		break;
269		}
270		}
271		}
272
273		void serializeTelemetryBuffer(FILE *outfile)
274		{
275		unsigned int serializationEnd = recordBufferIndex;
276		unsigned int serializationStart = lastSerializedIndex;
277
278		if(serializationEnd < serializationStart) {
279		serializeTelemetryBufferRange(outfile, serializationStart, RECORD_BUFFER_SIZE);
280		serializeTelemetryBufferRange(outfile, 0, serializationEnd);
281		} else {
282		serializeTelemetryBufferRange(outfile, serializationStart, serializationEnd);
283		}
284
285		lastSerializedIndex = serializationEnd;
286		}
287
288		void backgroundSerialization(void outfile)
289		{
290		while(continueBackgroundSerialization) {
291		MVM_sleep(500);
292		serializeTelemetryBuffer((FILE *)outfile);
293		}
294
295		fclose((FILE *)outfile);
296
297		return NULL;
298		}
299
300		MVM_PUBLIC void MVM_telemetry_init(FILE *outfile)
301		{
302		struct TelemetryRecord *calibrationRecord;
303		struct TelemetryRecord *epochRecord;
304		int threadCreateError;
305
306		telemetry_active = 1;
307
308		calibrateTSC(outfile);
309
310		calibrationRecord = newRecord();
311		calibrationRecord->u.calibration.ticksPerSecond = ticksPerSecond;
312		calibrationRecord->recordType = Calibration;
313
314		epochRecord = newRecord();
315		READ_TSC(epochRecord->u.epoch.time)
316		epochRecord->recordType = Epoch;
317
318		beginningEpoch = epochRecord->u.epoch.time;
319
320		threadCreateError = uv_thread_create(&backgroundSerializationThread, (uv_thread_cb)backgroundSerialization, (void *)outfile);
321		if (threadCreateError != 0) {
322		telemetry_active = 0;
323
324		fprintf(stderr, "MoarVM: Could not initialize telemetry: %s\n", uv_strerror(threadCreateError));
325		}
326		}
327
328		MVM_PUBLIC void MVM_telemetry_finish()
329		{
330		continueBackgroundSerialization = 0;
331		uv_thread_join(&backgroundSerializationThread);
332		}
333
334		#else
335
336	5.17k	MVM_PUBLIC void MVM_telemetry_timestamp(MVMThreadContext threadID, const char description) { }
337
338	6.08k	MVM_PUBLIC unsigned int MVM_telemetry_interval_start(MVMThreadContext threadID, const char description) { return 0; }
339	5.93k	MVM_PUBLIC void MVM_telemetry_interval_stop(MVMThreadContext threadID, int intervalID, const char description) { }
340	5.16k	MVM_PUBLIC void MVM_telemetry_interval_annotate(uintptr_t subject, int intervalID, const char *description) { }
341	3	MVM_PUBLIC void MVM_telemetry_interval_annotate_dynamic(uintptr_t subject, int intervalID, char *description) { }
342
343	0	MVM_PUBLIC void MVM_telemetry_init(FILE *outfile) { }
344	0	MVM_PUBLIC void MVM_telemetry_finish() { }
345
346		#endif