Log time that specialization work consumes.

MoarVM · Jul 19, 2017 · 9bcbc02 · 9bcbc02
1 parent 6e3b3cb
commit 9bcbc02
Show file tree

Hide file tree

Showing 2 changed files with 15 additions and 5 deletions.
diff --git a/src/spesh/candidate.c b/src/spesh/candidate.c
@@ -26,6 +26,7 @@ void MVM_spesh_candidate_add(MVMThreadContext *tc, MVMSpeshPlanned *p) {
     MVMSpeshCode *sc;
     MVMSpeshCandidate *candidate;
     MVMSpeshCandidate **new_candidate_list;
+    MVMuint64 start_time;
 
     /* If we've reached our specialization limit, don't continue. */
     if (tc->instance->spesh_limit)
@@ -37,6 +38,8 @@ void MVM_spesh_candidate_add(MVMThreadContext *tc, MVMSpeshPlanned *p) {
 #if MVM_GC_DEBUG
     tc->in_spesh = 1;
 #endif
+    if (tc->instance->spesh_log_fh)
+        start_time = uv_hrtime();
     sg = MVM_spesh_graph_create(tc, p->sf, 0, 1);
     if (tc->instance->spesh_log_fh) {
         char *c_name = MVM_string_utf8_encode_C_string(tc, p->sf->body.name);
@@ -57,7 +60,9 @@ void MVM_spesh_candidate_add(MVMThreadContext *tc, MVMSpeshPlanned *p) {
     MVM_spesh_optimize(tc, sg);
     if (tc->instance->spesh_log_fh) {
         char *after = MVM_spesh_dump(tc, sg);
-        fprintf(tc->instance->spesh_log_fh, "After:\n%s========\n\n", after);
+        fprintf(tc->instance->spesh_log_fh, "After:\n%s", after);
+        fprintf(tc->instance->spesh_log_fh, "Specialization took %dus\n\n========\n\n",
+            (int)((uv_hrtime() - start_time) / 1000));
         MVM_free(after);
     }
 

diff --git a/src/spesh/worker.c b/src/spesh/worker.c
@@ -17,17 +17,20 @@ static void worker(MVMThreadContext *tc, MVMCallsite *callsite, MVMRegister *arg
                     MVMThreadContext *stc;
                     MVMuint32 i;
                     MVMuint32 n;
+                    MVMuint64 start_time;
 
                     /* Update stats, and if we're logging dump each of them. */
                     tc->instance->spesh_stats_version++;
+                    if (tc->instance->spesh_log_fh)
+                        start_time = uv_hrtime();
                     MVM_spesh_stats_update(tc, sl, updated_static_frames);
                     if (tc->instance->spesh_log_fh) {
                         n = MVM_repr_elems(tc, updated_static_frames);
                         fprintf(tc->instance->spesh_log_fh,
                             "Statistics Updated\n"
                             "==================\n"
-                            "%d frames had their statistics updated.\n\n",
-                            (int)n);
+                            "%d frames had their statistics updated in %dus.\n\n",
+                            (int)n, (int)((uv_hrtime() - start_time) / 1000));
                         for (i = 0; i < n; i++) {
                             char *dump = MVM_spesh_dump_stats(tc, (MVMStaticFrame* )
                                 MVM_repr_at_pos_o(tc, updated_static_frames, i));
@@ -38,14 +41,16 @@ static void worker(MVMThreadContext *tc, MVMCallsite *callsite, MVMRegister *arg
                     GC_SYNC_POINT(tc);
 
                     /* Form a specialization plan. */
+                    if (tc->instance->spesh_log_fh)
+                        start_time = uv_hrtime();
                     tc->instance->spesh_plan = MVM_spesh_plan(tc, updated_static_frames);
                     if (tc->instance->spesh_log_fh) {
                         n = tc->instance->spesh_plan->num_planned;
                         fprintf(tc->instance->spesh_log_fh,
                             "Specialization Plan\n"
                             "===================\n"
-                            "%u specialization(s) will be produced.\n\n",
-                            n);
+                            "%u specialization(s) will be produced (planned in %dus).\n\n",
+                            n, (int)((uv_hrtime() - start_time) / 1000));
                         for (i = 0; i < n; i++) {
                             char *dump = MVM_spesh_dump_planned(tc,
                                 &(tc->instance->spesh_plan->planned[i]));