/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 | } |