Coverage Report

Created: 2018-07-03 15:31

/home/travis/build/MoarVM/MoarVM/src/profiler/log.c
Line
Count
Source (jump to first uncovered line)
1
#include "moar.h"
2
3
/* Gets the current thread's profiling data structure, creating it if needed. */
4
0
static MVMProfileThreadData * get_thread_data(MVMThreadContext *tc) {
5
0
    if (!tc->prof_data) {
6
0
        tc->prof_data = MVM_calloc(1, sizeof(MVMProfileThreadData));
7
0
        tc->prof_data->start_time = uv_hrtime();
8
0
    }
9
0
    return tc->prof_data;
10
0
}
11
12
/* Log that we're entering a new frame. */
13
0
void MVM_profile_log_enter(MVMThreadContext *tc, MVMStaticFrame *sf, MVMuint64 mode) {
14
0
    MVMProfileThreadData *ptd = get_thread_data(tc);
15
0
16
0
    /* Try to locate the entry node, if it's in the call graph already. */
17
0
    MVMProfileCallNode *pcn = NULL;
18
0
    MVMuint32 i;
19
0
    if (ptd->current_call)
20
0
        for (i = 0; i < ptd->current_call->num_succ; i++)
21
0
            if (ptd->current_call->succ[i]->sf == sf)
22
0
                pcn = ptd->current_call->succ[i];
23
0
24
0
    /* If we didn't find a call graph node, then create one and add it to the
25
0
     * graph. */
26
0
    if (!pcn) {
27
0
        pcn     = MVM_calloc(1, sizeof(MVMProfileCallNode));
28
0
        pcn->sf = sf;
29
0
        if (ptd->current_call) {
30
0
            MVMProfileCallNode *pred = ptd->current_call;
31
0
            pcn->pred = pred;
32
0
            if (pred->num_succ == pred->alloc_succ) {
33
0
                pred->alloc_succ += 8;
34
0
                pred->succ = MVM_realloc(pred->succ,
35
0
                    pred->alloc_succ * sizeof(MVMProfileCallNode *));
36
0
            }
37
0
            pred->succ[pred->num_succ] = pcn;
38
0
            pred->num_succ++;
39
0
        }
40
0
        else {
41
0
            if (!ptd->call_graph)
42
0
                ptd->call_graph = pcn;
43
0
        }
44
0
    }
45
0
46
0
    /* Increment entry counts. */
47
0
    pcn->total_entries++;
48
0
    switch (mode) {
49
0
        case MVM_PROFILE_ENTER_SPESH:
50
0
            pcn->specialized_entries++;
51
0
            break;
52
0
        case MVM_PROFILE_ENTER_SPESH_INLINE:
53
0
            pcn->specialized_entries++;
54
0
            pcn->inlined_entries++;
55
0
            break;
56
0
        case MVM_PROFILE_ENTER_JIT:
57
0
            pcn->jit_entries++;
58
0
            break;
59
0
        case MVM_PROFILE_ENTER_JIT_INLINE:
60
0
            pcn->jit_entries++;
61
0
            pcn->inlined_entries++;
62
0
            break;
63
0
    }
64
0
    pcn->entry_mode = mode;
65
0
66
0
    /* Log entry time; clear skip time. */
67
0
    pcn->cur_entry_time = uv_hrtime();
68
0
    pcn->cur_skip_time  = 0;
69
0
70
0
    /* The current call graph node becomes this one. */
71
0
    ptd->current_call = pcn;
72
0
}
73
74
/* Log that we've entered a native routine */
75
0
void MVM_profile_log_enter_native(MVMThreadContext *tc, MVMObject *nativecallsite) {
76
0
    MVMProfileThreadData *ptd = get_thread_data(tc);
77
0
    MVMProfileCallNode *pcn = NULL;
78
0
    MVMNativeCallBody *callbody;
79
0
    MVMuint32 i;
80
0
81
0
    /* We locate the right call node by looking at sf being NULL and the
82
0
     * native_target_name matching our intended target. */
83
0
    callbody = MVM_nativecall_get_nc_body(tc, nativecallsite);
84
0
    if (ptd->current_call)
85
0
        for (i = 0; i < ptd->current_call->num_succ; i++)
86
0
            if (ptd->current_call->succ[i]->sf == NULL)
87
0
                if (strcmp(callbody->sym_name,
88
0
                           ptd->current_call->succ[i]->native_target_name) == 0) {
89
0
                    pcn = ptd->current_call->succ[i];
90
0
                    break;
91
0
                }
92
0
93
0
    /* If we didn't find a call graph node, then create one and add it to the
94
0
     * graph. */
95
0
    if (!pcn) {
96
0
        pcn     = MVM_calloc(1, sizeof(MVMProfileCallNode));
97
0
        pcn->native_target_name = callbody->sym_name;
98
0
        if (ptd->current_call) {
99
0
            MVMProfileCallNode *pred = ptd->current_call;
100
0
            pcn->pred = pred;
101
0
            if (pred->num_succ == pred->alloc_succ) {
102
0
                pred->alloc_succ += 8;
103
0
                pred->succ = MVM_realloc(pred->succ,
104
0
                    pred->alloc_succ * sizeof(MVMProfileCallNode *));
105
0
            }
106
0
            pred->succ[pred->num_succ] = pcn;
107
0
            pred->num_succ++;
108
0
        }
109
0
        else {
110
0
            if (!ptd->call_graph)
111
0
                ptd->call_graph = pcn;
112
0
        }
113
0
    }
114
0
115
0
    /* Increment entry counts. */
116
0
    pcn->total_entries++;
117
0
    pcn->entry_mode = 0;
118
0
119
0
    /* Log entry time; clear skip time. */
120
0
    pcn->cur_entry_time = uv_hrtime();
121
0
    pcn->cur_skip_time  = 0;
122
0
123
0
    /* The current call graph node becomes this one. */
124
0
    ptd->current_call = pcn;
125
0
}
126
127
/* Frame exit handler, used for unwind and normal exit. */
128
0
static void log_exit(MVMThreadContext *tc, MVMuint32 unwind) {
129
0
    MVMProfileThreadData *ptd = get_thread_data(tc);
130
0
131
0
    /* Ensure we've a current frame. */
132
0
    MVMProfileCallNode *pcn = ptd->current_call;
133
0
    if (!pcn) {
134
0
        if (tc->instance->profiling) {
135
0
            /* No frame but still profiling; corruption. */
136
0
            MVM_dump_backtrace(tc);
137
0
            MVM_panic(1, "Profiler lost sequence");
138
0
        }
139
0
        else {
140
0
            /* We already finished profiling. */
141
0
            return;
142
0
        }
143
0
    }
144
0
145
0
    /* Add to total time. */
146
0
    pcn->total_time += (uv_hrtime() - pcn->cur_entry_time) - pcn->cur_skip_time;
147
0
148
0
    /* Move back to predecessor in call graph. */
149
0
    ptd->current_call = pcn->pred;
150
0
}
151
152
/* Log that we're exiting a frame normally. */
153
0
void MVM_profile_log_exit(MVMThreadContext *tc) {
154
0
    log_exit(tc, 0);
155
0
}
156
157
/* Called when we unwind. Since we're also potentially leaving some inlined
158
 * frames, we need to exit until we hit the target one. */
159
0
void MVM_profile_log_unwind(MVMThreadContext *tc) {
160
0
    MVMProfileThreadData *ptd  = get_thread_data(tc);
161
0
    MVMProfileCallNode   *lpcn;
162
0
    do {
163
0
        MVMProfileCallNode *pcn  = ptd->current_call;
164
0
        if (!pcn)
165
0
            return;
166
0
        lpcn = pcn;
167
0
        log_exit(tc, 1);
168
0
    } while (lpcn->sf != tc->cur_frame->static_info);
169
0
}
170
171
/* Called when we take a continuation. Leaves the static frames from the point
172
 * of view of the profiler, and saves each of them. */
173
0
MVMProfileContinuationData * MVM_profile_log_continuation_control(MVMThreadContext *tc, const MVMFrame *root_frame) {
174
0
    MVMProfileThreadData        *ptd       = get_thread_data(tc);
175
0
    MVMProfileContinuationData  *cd        = MVM_malloc(sizeof(MVMProfileContinuationData));
176
0
    MVMStaticFrame             **sfs       = NULL;
177
0
    MVMuint64                   *modes     = NULL;
178
0
    MVMFrame                    *cur_frame = tc->cur_frame;
179
0
    MVMuint64                    alloc_sfs = 0;
180
0
    MVMuint64                    num_sfs   = 0;
181
0
    MVMFrame                   *last_frame;
182
0
183
0
    do {
184
0
        MVMProfileCallNode   *lpcn;
185
0
        do {
186
0
            MVMProfileCallNode *pcn = ptd->current_call;
187
0
            if (!pcn)
188
0
                MVM_panic(1, "Profiler lost sequence in continuation control");
189
0
190
0
            if (num_sfs == alloc_sfs) {
191
0
                alloc_sfs += 16;
192
0
                sfs        = MVM_realloc(sfs, alloc_sfs * sizeof(MVMStaticFrame *));
193
0
                modes      = MVM_realloc(modes, alloc_sfs * sizeof(MVMuint64));
194
0
            }
195
0
            sfs[num_sfs]   = pcn->sf;
196
0
            modes[num_sfs] = pcn->entry_mode;
197
0
            num_sfs++;
198
0
199
0
            lpcn = pcn;
200
0
            log_exit(tc, 1);
201
0
        } while (lpcn->sf != cur_frame->static_info);
202
0
203
0
        last_frame = cur_frame;
204
0
        cur_frame = cur_frame->caller;
205
0
    } while (last_frame != root_frame);
206
0
207
0
    cd->sfs     = sfs;
208
0
    cd->num_sfs = num_sfs;
209
0
    cd->modes   = modes;
210
0
    return cd;
211
0
}
212
213
/* Called when we invoke a continuation. Enters all the static frames we left
214
 * at the point we took the continuation. */
215
0
void MVM_profile_log_continuation_invoke(MVMThreadContext *tc, const MVMProfileContinuationData *cd) {
216
0
    MVMuint64 i = cd->num_sfs;
217
0
    while (i--)
218
0
        MVM_profile_log_enter(tc, cd->sfs[i], cd->modes[i]);
219
0
}
220
221
/* Log that we've just allocated the passed object (just log the type). */
222
0
void MVM_profile_log_allocated(MVMThreadContext *tc, MVMObject *obj) {
223
0
    MVMProfileThreadData *ptd  = get_thread_data(tc);
224
0
    MVMProfileCallNode   *pcn  = ptd->current_call;
225
0
    if (pcn) {
226
0
        /* First, let's see if the allocation is actually at the end of the
227
0
         * nursery; we may have generated some "allocated" log instructions
228
0
         * after operations that may or may not allocate what they return.
229
0
         */
230
0
        MVMuint32 distance = ((MVMuint64)tc->nursery_alloc - (MVMuint64)obj);
231
0
232
0
        if (!obj) {
233
0
            return;
234
0
        }
235
0
236
0
        /* Since some ops first allocate, then call something else that may
237
0
         * also allocate, we may have to allow for a bit of grace distance. */
238
0
        if ((MVMuint64)obj > (MVMuint64)tc->nursery_tospace && distance <= obj->header.size && obj != ptd->last_counted_allocation) {
239
0
            /* See if there's an existing node to update. */
240
0
            MVMObject            *what = STABLE(obj)->WHAT;
241
0
            MVMuint32 i;
242
0
243
0
            MVMuint8 allocation_target;
244
0
            if (pcn->entry_mode == MVM_PROFILE_ENTER_SPESH || pcn->entry_mode == MVM_PROFILE_ENTER_SPESH_INLINE) {
245
0
                allocation_target = 1;
246
0
            } else if (pcn->entry_mode == MVM_PROFILE_ENTER_JIT || pcn->entry_mode == MVM_PROFILE_ENTER_JIT_INLINE) {
247
0
                allocation_target = 2;
248
0
            } else {
249
0
                allocation_target = 0;
250
0
            }
251
0
252
0
            for (i = 0; i < pcn->num_alloc; i++) {
253
0
                if (pcn->alloc[i].type == what) {
254
0
                    if (allocation_target == 0)
255
0
                        pcn->alloc[i].allocations_interp++;
256
0
                    else if (allocation_target == 1)
257
0
                        pcn->alloc[i].allocations_spesh++;
258
0
                    else if (allocation_target == 2)
259
0
                        pcn->alloc[i].allocations_jit++;
260
0
                    ptd->last_counted_allocation = obj;
261
0
                    return;
262
0
                }
263
0
            }
264
0
265
0
            /* No entry; create one. */
266
0
            if (pcn->num_alloc == pcn->alloc_alloc) {
267
0
                pcn->alloc_alloc += 8;
268
0
                pcn->alloc = MVM_realloc(pcn->alloc,
269
0
                    pcn->alloc_alloc * sizeof(MVMProfileAllocationCount));
270
0
            }
271
0
            pcn->alloc[pcn->num_alloc].type        = what;
272
0
            pcn->alloc[pcn->num_alloc].allocations_interp = allocation_target == 0;
273
0
            pcn->alloc[pcn->num_alloc].allocations_spesh  = allocation_target == 1;
274
0
            pcn->alloc[pcn->num_alloc].allocations_jit    = allocation_target == 2;
275
0
            ptd->last_counted_allocation = obj;
276
0
            pcn->num_alloc++;
277
0
        }
278
0
    }
279
0
}
280
281
/* Logs the start of a GC run. */
282
0
void MVM_profiler_log_gc_start(MVMThreadContext *tc, MVMuint32 full, MVMuint32 this_thread_responsible) {
283
0
    MVMProfileThreadData *ptd = get_thread_data(tc);
284
0
    MVMProfileGC *gc;
285
0
286
0
    /* Make a new entry in the GCs. We use the cleared_bytes to store the
287
0
     * maximum that could be cleared, and after GC is done will subtract
288
0
     * retained bytes and promoted bytes. */
289
0
    if (ptd->num_gcs == ptd->alloc_gcs) {
290
0
        ptd->alloc_gcs += 16;
291
0
        ptd->gcs = MVM_realloc(ptd->gcs, ptd->alloc_gcs * sizeof(MVMProfileGC));
292
0
    }
293
0
    gc = &ptd->gcs[ptd->num_gcs];
294
0
    gc->full          = full;
295
0
    gc->cleared_bytes = (char *)tc->nursery_alloc -
296
0
                        (char *)tc->nursery_tospace;
297
0
    gc->responsible   = this_thread_responsible;
298
0
    gc->gc_seq_num    = MVM_load(&tc->instance->gc_seq_number);
299
0
300
0
    /* Record start time. */
301
0
    ptd->cur_gc_start_time = uv_hrtime();
302
0
    /* Also store this time in the GC data */
303
0
    gc->abstime = ptd->cur_gc_start_time;
304
0
}
305
306
/* Logs the end of a GC run. */
307
0
void MVM_profiler_log_gc_end(MVMThreadContext *tc) {
308
0
    MVMProfileThreadData *ptd = get_thread_data(tc);
309
0
    MVMProfileCallNode   *pcn = ptd->current_call;
310
0
    MVMuint64 gc_time;
311
0
    MVMint32  retained_bytes;
312
0
313
0
    /* Record time spent. */
314
0
    gc_time = uv_hrtime() - ptd->cur_gc_start_time;
315
0
    ptd->gcs[ptd->num_gcs].time = gc_time;
316
0
317
0
    /* Record retained and promoted bytes. */
318
0
    retained_bytes = (char *)tc->nursery_alloc - (char *)tc->nursery_tospace;
319
0
    ptd->gcs[ptd->num_gcs].promoted_bytes = tc->gc_promoted_bytes;
320
0
    ptd->gcs[ptd->num_gcs].retained_bytes = retained_bytes;
321
0
322
0
    /* Tweak cleared bytes count. */
323
0
    ptd->gcs[ptd->num_gcs].cleared_bytes -= (retained_bytes + tc->gc_promoted_bytes);
324
0
325
0
    /* Record number of gen 2 roots (from gen2 to nursery) */
326
0
    ptd->gcs[ptd->num_gcs].num_gen2roots = tc->num_gen2roots;
327
0
328
0
    /* Increment the number of GCs we've done. */
329
0
    ptd->num_gcs++;
330
0
331
0
    /* Discount GC time from all active frames. */
332
0
    while (pcn) {
333
0
        pcn->cur_skip_time += gc_time;
334
0
        pcn = pcn->pred;
335
0
    }
336
0
}
337
338
/* Log that we're starting some work on bytecode specialization or JIT. */
339
0
void MVM_profiler_log_spesh_start(MVMThreadContext *tc) {
340
0
    /* Record start time. */
341
0
    MVMProfileThreadData *ptd = get_thread_data(tc->instance->main_thread);
342
0
    ptd->cur_spesh_start_time = uv_hrtime();
343
0
}
344
345
/* Log that we've finished doing bytecode specialization or JIT. */
346
0
void MVM_profiler_log_spesh_end(MVMThreadContext *tc) {
347
0
    MVMProfileThreadData *ptd = get_thread_data(tc->instance->main_thread);
348
0
    MVMuint64 spesh_time;
349
0
350
0
    /* Because spesh workers might start before profiling starts,
351
0
     * MVM_profiler_log_spesh_end might get called before
352
0
     * MVM_profiler_log_spesh_start. */
353
0
    if (ptd->cur_spesh_start_time == 0)
354
0
        ptd->cur_spesh_start_time = ptd->start_time;
355
0
356
0
    /* Record time spent. */
357
0
    spesh_time = uv_hrtime() - ptd->cur_spesh_start_time;
358
0
    ptd->spesh_time += spesh_time;
359
0
}
360
361
/* Log that an on stack replacement took place. */
362
0
void MVM_profiler_log_osr(MVMThreadContext *tc, MVMuint64 jitted) {
363
0
    MVMProfileThreadData *ptd = get_thread_data(tc);
364
0
    MVMProfileCallNode   *pcn = ptd->current_call;
365
0
    if (pcn) {
366
0
        pcn->osr_count++;
367
0
        if (jitted)
368
0
            pcn->jit_entries++;
369
0
        else
370
0
            pcn->specialized_entries++;
371
0
    }
372
0
}
373
374
/* Log that local deoptimization took pace. */
375
0
void MVM_profiler_log_deopt_one(MVMThreadContext *tc) {
376
0
    MVMProfileThreadData *ptd = get_thread_data(tc);
377
0
    MVMProfileCallNode   *pcn = ptd->current_call;
378
0
    if (pcn)
379
0
        pcn->deopt_one_count++;
380
0
}
381
382
/* Log that full-stack deoptimization took pace. */
383
0
void MVM_profiler_log_deopt_all(MVMThreadContext *tc) {
384
0
    MVMProfileThreadData *ptd = get_thread_data(tc);
385
0
    MVMProfileCallNode   *pcn = ptd->current_call;
386
0
    if (pcn)
387
0
        pcn->deopt_all_count++;
388
0
}