From 04e407c8b3cf60897ed50d95986eb60fb2178568 Mon Sep 17 00:00:00 2001 From: Jelle Foks Date: Fri, 16 Aug 2024 12:35:58 -0700 Subject: [PATCH] Log thread and process CPU time --- cobalt/script/v8c/v8c_script_debugger.cc | 37 ++++++++++++++++--- .../http_stream_factory_job_controller.cc | 25 ++++++++++++- net/http/http_stream_factory_job_controller.h | 1 + 3 files changed, 55 insertions(+), 8 deletions(-) diff --git a/cobalt/script/v8c/v8c_script_debugger.cc b/cobalt/script/v8c/v8c_script_debugger.cc index ff06e6c8949e..b87728bcb143 100644 --- 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 + #include #include #include @@ -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 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 index 3cab6334752b..f04518599913 100644 --- 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 #include #include @@ -33,6 +34,7 @@ #include "net/log/net_log_with_source.h" #include "net/proxy_resolution/proxy_resolution_request.h" #include "net/spdy/spdy_session.h" +#include "starboard/common/string.h" #include "url/gurl.h" #include "url/scheme_host_port.h" #include "url/third_party/mozilla/url_parse.h" @@ -130,6 +132,25 @@ base::Value::Dict NetLogAltSvcParams(const AlternativeServiceInfo* alt_svc_info, return 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, @@ -311,7 +332,7 @@ void HttpStreamFactory::JobController::OnStreamReady( { const char* jobtypename[] = {"main", "alternative", "dns_alpn_h3", "preconnect", "preconnect_dns_alpn_h3"}; - LOG(INFO) << __FUNCTION__ << " negotiated_protocol = " + LOG(INFO) << __FUNCTION__ << print_clocks() << " negotiated_protocol = " << NextProtoToString(job->negotiated_protocol()) << " was_alpn_negotiated=" << job->was_alpn_negotiated() << " using_spdy=" << job->using_spdy() @@ -1224,7 +1245,7 @@ HttpStreamFactory::JobController::GetAlternativeServiceInfoInternal( // Leave the port restriction only in production builds to simplify testing #if defined(COBALT_BUILD_TYPE_GOLD) if (origin.port() == kDefaultQUICServerPort) { -#endif +#endif quic::ParsedQuicVersionVector versions = quic::AllSupportedVersions(); return AlternativeServiceInfo::CreateQuicAlternativeServiceInfo( AlternativeService(net::kProtoQUIC, origin.host(), diff --git a/net/http/http_stream_factory_job_controller.h b/net/http/http_stream_factory_job_controller.h index 0849ee79b30f..282a36099c92 100644 --- a/net/http/http_stream_factory_job_controller.h +++ b/net/http/http_stream_factory_job_controller.h @@ -379,6 +379,7 @@ class HttpStreamFactory::JobController const NetLogWithSource net_log_; base::WeakPtrFactory ptr_factory_{this}; + }; } // namespace net