perf: only time the fetch event when debug logging is enabled (#873)

Author: JakeChampion

runtime/fastly/builtins/fetch-event.cpp

@@ -425,10 +425,8 @@ bool FetchEvent::server_get(JSContext *cx, unsigned argc, JS::Value *vp) {
   return true;
 }
 
-void dispatch_fetch_event(HandleObject event, double *total_compute) {
+void dispatch_fetch_event(HandleObject event) {
   MOZ_ASSERT(FetchEvent::is_instance(event));
-  auto pre_handler = system_clock::now();
-
   RootedValue result(ENGINE->cx());
   RootedValue event_val(ENGINE->cx(), JS::ObjectValue(*event));
   HandleValueArray argsv = HandleValueArray(event_val);
@@ -449,11 +447,14 @@ void dispatch_fetch_event(HandleObject event, double *total_compute) {
   }
 
   FetchEvent::stop_dispatching(event);
+}
 
+void dispatch_fetch_event(HandleObject event, double *total_compute) {
+  auto pre_handler = system_clock::now();
+  dispatch_fetch_event(event);
   double diff = duration_cast<microseconds>(system_clock::now() - pre_handler).count();
   *total_compute += diff;
-  if (ENGINE->debug_logging_enabled())
-    printf("Request handler took %fms\n", diff / 1000);
+  printf("Request handler took %fms\n", diff / 1000);
 }
 
 JSObject *FetchEvent::prepare_downstream_request(JSContext *cx) {

runtime/fastly/builtins/fetch-event.h

@@ -56,6 +56,7 @@ class ServerInfo final : public builtins::BuiltinNoConstructor<ServerInfo> {
   static JSObject *create(JSContext *cx);
 };
 
+void dispatch_fetch_event(HandleObject event);
 void dispatch_fetch_event(HandleObject event, double *total_compute);
 
 class FetchEvent final : public builtins::BuiltinNoConstructor<FetchEvent> {

runtime/fastly/handler.cpp

@@ -27,7 +27,10 @@ void handle_incoming(host_api::Request req) {
       std::chrono::high_resolution_clock::now());
 
   double total_compute = 0;
-  auto start = system_clock::now();
+  std::chrono::system_clock::time_point start;
+  if (ENGINE->debug_logging_enabled()) {
+    start = system_clock::now();
+  }
 
   __wasilibc_initialize_environ();
 
@@ -43,7 +46,11 @@ void handle_incoming(host_api::Request req) {
     return;
   }
 
-  fastly::fetch_event::dispatch_fetch_event(fetch_event, &total_compute);
+  if (ENGINE->debug_logging_enabled()) {
+    fastly::fetch_event::dispatch_fetch_event(fetch_event, &total_compute);
+  } else {
+    fastly::fetch_event::dispatch_fetch_event(fetch_event);
+  }
 
   // Loop until no more resolved promises or backend requests are pending.
   if (ENGINE->debug_logging_enabled()) {
@@ -77,9 +84,9 @@ void handle_incoming(host_api::Request req) {
     return;
   }
 
-  auto end = system_clock::now();
-  double diff = duration_cast<microseconds>(end - start).count();
   if (ENGINE->debug_logging_enabled()) {
+    auto end = system_clock::now();
+    double diff = duration_cast<microseconds>(end - start).count();
     printf("Done. Total request processing time: %fms. Total compute time: %fms\n", diff / 1000,
            total_compute / 1000);
   }