Coverage Report

Created: 2018-07-03 15:31

/home/travis/build/MoarVM/MoarVM/src/spesh/log.c
Line
Count
Source (jump to first uncovered line)
1
#include "moar.h"
2
3
/* Provided spesh is enabled, set up specialization data logging for the
4
 * current thread. */
5
170
void MVM_spesh_log_initialize_thread(MVMThreadContext *tc, MVMint32 main_thread) {
6
170
    if (tc->instance->spesh_enabled) {
7
170
        tc->spesh_log = MVM_spesh_log_create(tc, tc->thread_obj);
8
170
        tc->spesh_log_quota = main_thread
9
144
            ? MVM_SPESH_LOG_QUOTA_MAIN_THREAD
10
26
            : MVM_SPESH_LOG_QUOTA;
11
170
    }
12
170
}
13
14
/* Creates a spesh log for the specified target thread. */
15
1.86k
MVMSpeshLog * MVM_spesh_log_create(MVMThreadContext *tc, MVMThread *target_thread) {
16
1.86k
    MVMSpeshLog *result;
17
1.86k
    MVMROOT(tc, target_thread, {
18
1.86k
        result = (MVMSpeshLog *)MVM_repr_alloc_init(tc, tc->instance->SpeshLog);
19
1.86k
        MVM_ASSIGN_REF(tc, &(result->common.header), result->body.thread, target_thread);
20
1.86k
    });
21
1.86k
    return result;
22
1.86k
}
23
24
/* Increments the used count and - if it hits the limit - sends the log off
25
 * to the worker thread and NULLs it out. */
26
1.69k
void send_log(MVMThreadContext *tc, MVMSpeshLog *sl) {
27
1.69k
    if (tc->instance->spesh_blocking) {
28
0
        uv_mutex_t *block_mutex;
29
0
        uv_cond_t *block_condvar;
30
0
        block_mutex = sl->body.block_mutex = MVM_malloc(sizeof(uv_mutex_t));
31
0
        uv_mutex_init(sl->body.block_mutex);
32
0
        block_condvar = sl->body.block_condvar = MVM_malloc(sizeof(uv_cond_t));
33
0
        uv_cond_init(sl->body.block_condvar);
34
0
        uv_mutex_lock(sl->body.block_mutex);
35
0
        MVMROOT(tc, sl, {
36
0
            MVM_repr_push_o(tc, tc->instance->spesh_queue, (MVMObject *)sl);
37
0
            MVM_gc_mark_thread_blocked(tc);
38
0
            while (!MVM_load(&(sl->body.completed)))
39
0
                uv_cond_wait(block_condvar, block_mutex);
40
0
            MVM_gc_mark_thread_unblocked(tc);
41
0
        });
42
0
        uv_mutex_unlock(sl->body.block_mutex);
43
0
    }
44
1.69k
    else {
45
1.69k
        MVM_repr_push_o(tc, tc->instance->spesh_queue, (MVMObject *)sl);
46
1.69k
    }
47
1.69k
    if (MVM_decr(&(tc->spesh_log_quota)) > 1) {
48
950
        tc->spesh_log = MVM_spesh_log_create(tc, tc->thread_obj);
49
950
    }
50
745
    else {
51
745
        MVM_telemetry_timestamp(tc, "ran out of spesh log quota");
52
745
        tc->spesh_log = NULL;
53
745
    }
54
1.69k
}
55
27.6M
void commit_entry(MVMThreadContext *tc, MVMSpeshLog *sl) {
56
27.6M
    sl->body.used++;
57
27.6M
    if (sl->body.used == sl->body.limit)
58
1.62k
        send_log(tc, sl);
59
27.6M
}
60
61
/* Handles the case where we enter a new compilation unit and have either no
62
 * spesh log or a spesh log that's quite full. This might hinder us in getting
63
 * enough data recorded for a tight outer loop in a benchmark. Either grant a
64
 * bonus log or send the log early so we can have a fresh one. */
65
1.21k
void MVM_spesh_log_new_compunit(MVMThreadContext *tc) {
66
1.21k
    if (tc->num_compunit_extra_logs++ < 5) {
67
168
        if (tc->spesh_log)
68
92
            if (tc->spesh_log->body.used > tc->spesh_log->body.limit / 4)
69
69
                send_log(tc, tc->spesh_log);
70
168
        if (!tc->spesh_log) {
71
130
            if (MVM_incr(&(tc->spesh_log_quota)) == 0) {
72
130
                tc->spesh_log = MVM_spesh_log_create(tc, tc->thread_obj);
73
130
                tc->spesh_log->body.was_compunit_bumped = 1;
74
130
            }
75
130
        }
76
168
    }
77
1.21k
}
78
79
/* Log the entry to a call frame. */
80
3.66M
void MVM_spesh_log_entry(MVMThreadContext *tc, MVMint32 cid, MVMStaticFrame *sf, MVMCallsite *cs) {
81
3.66M
    MVMSpeshLog *sl = tc->spesh_log;
82
3.66M
    if (sl) {
83
3.66M
        MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
84
3.66M
        entry->kind = MVM_SPESH_LOG_ENTRY;
85
3.66M
        entry->id = cid;
86
3.66M
        MVM_ASSIGN_REF(tc, &(sl->common.header), entry->entry.sf, sf);
87
3.58M
        entry->entry.cs = cs->is_interned ? cs : NULL;
88
3.66M
        commit_entry(tc, sl);
89
3.66M
    }
90
3.66M
}
91
92
/* Log an OSR point being hit. */
93
676k
void MVM_spesh_log_osr(MVMThreadContext *tc) {
94
676k
    MVMSpeshLog *sl = tc->spesh_log;
95
676k
    MVMint32 cid = tc->cur_frame->spesh_correlation_id;
96
676k
    MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
97
676k
    entry->kind = MVM_SPESH_LOG_OSR;
98
676k
    entry->id = cid;
99
676k
    entry->osr.bytecode_offset = (*(tc->interp_cur_op) - *(tc->interp_bytecode_start)) - 2;
100
676k
    commit_entry(tc, sl);
101
676k
}
102
103
/* Log a type. */
104
8.35M
void MVM_spesh_log_type(MVMThreadContext *tc, MVMObject *value) {
105
8.35M
    MVMSpeshLog *sl = tc->spesh_log;
106
8.35M
    MVMint32 cid = tc->cur_frame->spesh_correlation_id;
107
8.35M
    MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
108
8.35M
    entry->kind = MVM_SPESH_LOG_TYPE;
109
8.35M
    entry->id = cid;
110
8.35M
    MVM_ASSIGN_REF(tc, &(sl->common.header), entry->type.type, value->st->WHAT);
111
8.35M
    entry->type.flags = IS_CONCRETE(value) ? MVM_SPESH_LOG_TYPE_FLAG_CONCRETE : 0;
112
8.35M
    entry->type.bytecode_offset = (*(tc->interp_cur_op) - *(tc->interp_bytecode_start)) - 2;
113
8.35M
    commit_entry(tc, sl);
114
8.35M
}
115
116
/* Log a parameter type and, maybe, decontainerized type. */
117
static void log_param_type(MVMThreadContext *tc, MVMint32 cid, MVMuint16 arg_idx,
118
5.72M
                           MVMObject *value, MVMSpeshLogEntryKind kind, MVMint32 rw_cont) {
119
5.72M
    MVMSpeshLog *sl = tc->spesh_log;
120
5.72M
    MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
121
5.72M
    entry->kind = kind;
122
5.72M
    entry->id = cid;
123
5.72M
    MVM_ASSIGN_REF(tc, &(sl->common.header), entry->param.type, value->st->WHAT);
124
5.72M
    entry->param.flags = IS_CONCRETE(value) ? MVM_SPESH_LOG_TYPE_FLAG_CONCRETE : 0;
125
5.72M
    if (rw_cont)
126
0
        entry->param.flags |= MVM_SPESH_LOG_TYPE_FLAG_RW_CONT;
127
5.72M
    entry->param.arg_idx = arg_idx;
128
5.72M
    commit_entry(tc, sl);
129
5.72M
}
130
5.72M
void MVM_spesh_log_parameter(MVMThreadContext *tc, MVMuint16 arg_idx, MVMObject *param) {
131
5.72M
    MVMint32 cid = tc->cur_frame->spesh_correlation_id;
132
5.72M
    MVMContainerSpec const *cs = STABLE(param)->container_spec;
133
5.72M
    MVMROOT(tc, param, {
134
5.72M
        log_param_type(tc, cid, arg_idx, param, MVM_SPESH_LOG_PARAMETER,
135
5.72M
            cs && IS_CONCRETE(param) && cs->fetch_never_invokes
136
5.72M
                ? cs->can_store(tc, param)
137
5.72M
                : 0);
138
5.72M
    });
139
5.72M
    if (tc->spesh_log && IS_CONCRETE(param)) {
140
4.89M
        if (cs && cs->fetch_never_invokes && REPR(param)->ID != MVM_REPR_ID_NativeRef) {
141
0
            MVMRegister r;
142
0
            cs->fetch(tc, param, &r);
143
0
            log_param_type(tc, cid, arg_idx, r.o, MVM_SPESH_LOG_PARAMETER_DECONT, 0);
144
0
        }
145
4.89M
    }
146
5.72M
}
147
148
/* Log a static value. */
149
78.0k
void MVM_spesh_log_static(MVMThreadContext *tc, MVMObject *value) {
150
78.0k
    MVMSpeshLog *sl = tc->spesh_log;
151
78.0k
    MVMint32 cid = tc->cur_frame->spesh_correlation_id;
152
78.0k
    MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
153
78.0k
    entry->kind = MVM_SPESH_LOG_STATIC;
154
78.0k
    entry->id = cid;
155
78.0k
    MVM_ASSIGN_REF(tc, &(sl->common.header), entry->value.value, value);
156
78.0k
    entry->value.bytecode_offset = (*(tc->interp_cur_op) - *(tc->interp_bytecode_start)) - 2;
157
78.0k
    commit_entry(tc, sl);
158
78.0k
}
159
160
/* Log a decont, only those that did not invoke. */
161
27
void MVM_spesh_log_decont(MVMThreadContext *tc, MVMuint8 *prev_op, MVMObject *value) {
162
27
    MVMSpeshLog *sl = tc->spesh_log;
163
27
    MVMint32 cid = tc->cur_frame->spesh_correlation_id;
164
27
    if (prev_op + 4 == *(tc->interp_cur_op)) {
165
12
        MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
166
12
        entry->kind = MVM_SPESH_LOG_TYPE;
167
12
        entry->id = cid;
168
12
        MVM_ASSIGN_REF(tc, &(sl->common.header), entry->type.type, value->st->WHAT);
169
12
        entry->type.flags = IS_CONCRETE(value) ? MVM_SPESH_LOG_TYPE_FLAG_CONCRETE : 0;
170
12
        entry->type.bytecode_offset = (prev_op - *(tc->interp_bytecode_start)) - 2;
171
12
        commit_entry(tc, sl);
172
12
    }
173
27
}
174
175
/* Log the target of an invocation; we log the static frame and whether the
176
 * outer of the code object is the current frame. */
177
void MVM_spesh_log_invoke_target(MVMThreadContext *tc, MVMObject *invoke_target,
178
5.53M
                                 MVMuint16 was_multi) {
179
5.53M
    if (REPR(invoke_target)->ID == MVM_REPR_ID_MVMCode && IS_CONCRETE(invoke_target)) {
180
5.52M
        MVMCode *invoke_code = (MVMCode *)invoke_target;
181
5.52M
        MVMSpeshLog *sl = tc->spesh_log;
182
5.52M
        MVMint32 cid = tc->cur_frame->spesh_correlation_id;
183
5.52M
        MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
184
5.52M
        entry->kind = MVM_SPESH_LOG_INVOKE;
185
5.52M
        entry->id = cid;
186
5.52M
        MVM_ASSIGN_REF(tc, &(sl->common.header), entry->invoke.sf, invoke_code->body.sf);
187
5.52M
        entry->invoke.caller_is_outer = invoke_code->body.outer == tc->cur_frame;
188
5.52M
        entry->invoke.was_multi = was_multi;
189
5.52M
        entry->invoke.bytecode_offset = (*(tc->interp_cur_op) - *(tc->interp_bytecode_start)) - 2;
190
5.52M
        commit_entry(tc, sl);
191
5.52M
    }
192
5.53M
}
193
194
/* Log the type returned to a frame after an invocation. */
195
3.64M
void MVM_spesh_log_return_type(MVMThreadContext *tc, MVMObject *value) {
196
3.64M
    MVMSpeshLog *sl = tc->spesh_log;
197
3.64M
    MVMint32 cid = tc->cur_frame->spesh_correlation_id;
198
3.64M
    MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
199
3.64M
    entry->kind = MVM_SPESH_LOG_RETURN;
200
3.64M
    entry->id = cid;
201
3.64M
    if (value) {
202
3.00M
        MVM_ASSIGN_REF(tc, &(sl->common.header), entry->type.type, value->st->WHAT);
203
3.00M
        entry->type.flags = IS_CONCRETE(value) ? MVM_SPESH_LOG_TYPE_FLAG_CONCRETE : 0;
204
3.00M
    }
205
644k
    else {
206
644k
        entry->type.type = NULL;
207
644k
        entry->type.flags = 0;
208
644k
    }
209
3.64M
    entry->type.bytecode_offset = 0; /* Not relevant for this case. */
210
3.64M
    commit_entry(tc, sl);
211
3.64M
}
212
213
/* Log the result of a spesh plugin resolution. */
214
void MVM_spesh_log_plugin_resolution(MVMThreadContext *tc, MVMuint32 bytecode_offset,
215
5.73k
                                     MVMuint16 guard_index) {
216
5.73k
    MVMSpeshLog *sl = tc->spesh_log;
217
5.73k
    MVMint32 cid = tc->cur_frame->spesh_correlation_id;
218
5.73k
    MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
219
5.73k
    entry->kind = MVM_SPESH_LOG_PLUGIN_RESOLUTION;
220
5.73k
    entry->id = cid;
221
5.73k
    entry->plugin.bytecode_offset = bytecode_offset;
222
5.73k
    entry->plugin.guard_index = guard_index;
223
5.73k
    commit_entry(tc, sl);
224
5.73k
}