Log thread and process CPU time

youtube · Aug 16, 2024 · cc712b4 · cc712b4
1 parent a4aa9f5
commit cc712b4
Show file tree

Hide file tree

Showing 2 changed files with 55 additions and 10 deletions.
diff --git a/cobalt/script/v8c/v8c_script_debugger.cc b/cobalt/script/v8c/v8c_script_debugger.cc
@@ -14,6 +14,8 @@
 
 #include "cobalt/script/v8c/v8c_script_debugger.h"
 
+#include <pthread.h>
+
 #include <memory>
 #include <sstream>
 #include <string>
@@ -27,11 +29,31 @@
 #include "cobalt/script/v8c/conversion_helpers.h"
 #include "cobalt/script/v8c/v8c_tracing_controller.h"
 #include "include/inspector/Runtime.h"  // generated
+#include "starboard/common/string.h"
 #include "v8/include/libplatform/v8-tracing.h"
 #include "v8/include/v8-inspector.h"
 #include "v8/third_party/inspector_protocol/crdtp/json.h"
 #include "v8/third_party/inspector_protocol/crdtp/protocol_core.h"
 
+namespace {
+static clockid_t clockid = 0;
+std::string print_clock(const char* msg, clockid_t cid) {
+  struct timespec ts;
+  if (clock_gettime(cid, &ts) != -1)
+    return starboard::FormatString(" %s %ld.%06ld", msg, ts.tv_sec,
+                                   ts.tv_nsec / 1000);
+  return std::string();
+}
+
+std::string print_clocks() {
+  if (clockid == 0) {
+    pthread_getcpuclockid(pthread_self(), &clockid);
+  }
+  return print_clock("thread", clockid) +
+         print_clock("process", CLOCK_PROCESS_CPUTIME_ID);
+}
+}  // namespace
+
 namespace v8_crdtp {
 template <typename T>
 struct ProtocolTypeTraits<
@@ -381,22 +403,25 @@ void V8cScriptDebugger::consoleAPIMessage(
   std::string msg(FromStringView(message));
   switch (level) {
     case v8::Isolate::kMessageLog:
-      LOG(INFO) << "[console.log()" << source << "] " << msg;
+      LOG(INFO) << print_clocks() << "[console.log()" << source << "] " << msg;
       break;
     case v8::Isolate::kMessageDebug:
-      LOG(INFO) << "[console.debug()" << source << "] " << msg;
+      LOG(INFO) << print_clocks() << "[console.debug()" << source << "] "
+                << msg;
       break;
     case v8::Isolate::kMessageInfo:
-      LOG(INFO) << "[console.info()" << source << "] " << msg;
+      LOG(INFO) << print_clocks() << "[console.info()" << source << "] " << msg;
       break;
     case v8::Isolate::kMessageError:
-      LOG(ERROR) << "[console.error()" << source << "] " << msg;
+      LOG(ERROR) << print_clocks() << "[console.error()" << source << "] "
+                 << msg;
       break;
     case v8::Isolate::kMessageWarning:
-      LOG(WARNING) << "[console.warn()" << source << "] " << msg;
+      LOG(WARNING) << print_clocks() << "[console.warn()" << source << "] "
+                   << msg;
       break;
     case v8::Isolate::kMessageAll:
-      NOTIMPLEMENTED() << "Invalid MessageErrorLevel";
+      NOTIMPLEMENTED() << print_clocks() << "Invalid MessageErrorLevel";
       break;
   }
 }

diff --git a/net/http/http_stream_factory_job_controller.cc b/net/http/http_stream_factory_job_controller.cc
@@ -4,6 +4,7 @@
 
 #include "net/http/http_stream_factory_job_controller.h"
 
+#include <pthread.h>
 #include <string>
 #include <utility>
 
@@ -23,6 +24,7 @@
 #include "net/log/net_log_source.h"
 #include "net/log/net_log_with_source.h"
 #include "net/spdy/spdy_session.h"
+#include "starboard/common/string.h"
 #include "url/url_constants.h"
 
 namespace net {
@@ -61,6 +63,25 @@ std::unique_ptr<base::Value> NetLogJobControllerCallback(
   return std::move(dict);
 }
 
+namespace {
+static clockid_t clockid = 0;
+std::string print_clock(const char* msg, clockid_t cid) {
+  struct timespec ts;
+  if (clock_gettime(cid, &ts) != -1)
+    return starboard::FormatString(" %s %ld.%06ld", msg, ts.tv_sec,
+                                   ts.tv_nsec / 1000);
+  return std::string();
+}
+
+std::string print_clocks() {
+  if (clockid == 0) {
+    pthread_getcpuclockid(pthread_self(), &clockid);
+  }
+  return print_clock("thread", clockid) +
+         print_clock("process", CLOCK_PROCESS_CPUTIME_ID);
+}
+}  // namespace
+
 HttpStreamFactory::JobController::JobController(
     HttpStreamFactory* factory,
     HttpStreamRequest::Delegate* delegate,
@@ -256,9 +277,9 @@ void HttpStreamFactory::JobController::OnStreamReady(
   DCHECK(stream);
 
   {
-    const char* jobtypename[] = {"main", "alternative", "dns_alpn_h3", "preconnect",
-                           "preconnect_dns_alpn_h3"};
-    LOG(INFO) << __FUNCTION__ << " negotiated_protocol = "
+    const char* jobtypename[] = {"main", "alternative", "dns_alpn_h3",
+                                 "preconnect", "preconnect_dns_alpn_h3"};
+    LOG(INFO) << __FUNCTION__ << print_clocks() << " negotiated_protocol = "
               << NextProtoToString(job->negotiated_protocol())
               << " was_alpn_negotiated=" << job->was_alpn_negotiated()
               << " using_spdy=" << job->using_spdy()
@@ -509,7 +530,6 @@ void HttpStreamFactory::JobController::OnNewSpdySessionReady(
 
   // Notify |request_|.
   if (!is_preconnect_ && !is_job_orphaned) {
-
     DCHECK(request_);
 
     // The first case is the usual case.