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