#include "node_internals.h" #include "node_perf.h" #ifdef __POSIX__ #include // gettimeofday #endif namespace node { namespace performance { using v8::Array; using v8::Context; using v8::Function; using v8::FunctionCallbackInfo; using v8::FunctionTemplate; using v8::HandleScope; using v8::Integer; using v8::Isolate; using v8::Local; using v8::Name; using v8::Number; using v8::Object; using v8::String; using v8::Value; // Microseconds in a second, as a float. #define MICROS_PER_SEC 1e6 // Microseconds in a millisecond, as a float. #define MICROS_PER_MILLIS 1e3 // https://w3c.github.io/hr-time/#dfn-time-origin const uint64_t timeOrigin = PERFORMANCE_NOW(); // https://w3c.github.io/hr-time/#dfn-time-origin-timestamp const double timeOriginTimestamp = GetCurrentTimeInMicroseconds(); uint64_t performance_node_start; uint64_t performance_v8_start; uint64_t performance_last_gc_start_mark_ = 0; v8::GCType performance_last_gc_type_ = v8::GCType::kGCTypeAll; void performance_state::Mark(enum PerformanceMilestone milestone, uint64_t ts) { this->milestones[milestone] = ts; TRACE_EVENT_INSTANT_WITH_TIMESTAMP0( TRACING_CATEGORY_NODE1(bootstrap), GetPerformanceMilestoneName(milestone), TRACE_EVENT_SCOPE_THREAD, ts / 1000); } double GetCurrentTimeInMicroseconds() { #ifdef _WIN32 // The difference between the Unix Epoch and the Windows Epoch in 100-ns ticks. #define TICKS_TO_UNIX_EPOCH 116444736000000000LL FILETIME ft; GetSystemTimeAsFileTime(&ft); uint64_t filetime_int = static_cast(ft.dwHighDateTime) << 32 | ft.dwLowDateTime; // FILETIME is measured in terms of 100 ns. Convert that to 1 us (1000 ns). return (filetime_int - TICKS_TO_UNIX_EPOCH) / 10.; #else struct timeval tp; gettimeofday(&tp, nullptr); return MICROS_PER_SEC * tp.tv_sec + tp.tv_usec; #endif } // Initialize the performance entry object properties inline void InitObject(const PerformanceEntry& entry, Local obj) { Environment* env = entry.env(); Isolate* isolate = env->isolate(); Local context = env->context(); v8::PropertyAttribute attr = static_cast(v8::ReadOnly | v8::DontDelete); obj->DefineOwnProperty(context, env->name_string(), String::NewFromUtf8(isolate, entry.name().c_str(), v8::NewStringType::kNormal) .ToLocalChecked(), attr) .FromJust(); obj->DefineOwnProperty(context, env->entry_type_string(), String::NewFromUtf8(isolate, entry.type().c_str(), v8::NewStringType::kNormal) .ToLocalChecked(), attr) .FromJust(); obj->DefineOwnProperty(context, env->start_time_string(), Number::New(isolate, entry.startTime()), attr).FromJust(); obj->DefineOwnProperty(context, env->duration_string(), Number::New(isolate, entry.duration()), attr).FromJust(); } // Create a new PerformanceEntry object const Local PerformanceEntry::ToObject() const { Local obj = env_->performance_entry_template() ->NewInstance(env_->context()).ToLocalChecked(); InitObject(*this, obj); return obj; } // Allow creating a PerformanceEntry object from JavaScript void PerformanceEntry::New(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); Isolate* isolate = env->isolate(); Utf8Value name(isolate, args[0]); Utf8Value type(isolate, args[1]); uint64_t now = PERFORMANCE_NOW(); PerformanceEntry entry(env, *name, *type, now, now); Local obj = args.This(); InitObject(entry, obj); PerformanceEntry::Notify(env, entry.kind(), obj); } // Pass the PerformanceEntry object to the PerformanceObservers void PerformanceEntry::Notify(Environment* env, PerformanceEntryType type, Local object) { Context::Scope scope(env->context()); AliasedBuffer& observers = env->performance_state()->observers; if (type != NODE_PERFORMANCE_ENTRY_TYPE_INVALID && observers[type]) { node::MakeCallback(env->isolate(), object.As(), env->performance_entry_callback(), 1, &object, node::async_context{0, 0}); } } // Create a User Timing Mark void Mark(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); HandleScope scope(env->isolate()); Utf8Value name(env->isolate(), args[0]); uint64_t now = PERFORMANCE_NOW(); auto marks = env->performance_marks(); (*marks)[*name] = now; TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP( TRACING_CATEGORY_NODE2(perf, usertiming), *name, now / 1000); PerformanceEntry entry(env, *name, "mark", now, now); Local obj = entry.ToObject(); PerformanceEntry::Notify(env, entry.kind(), obj); args.GetReturnValue().Set(obj); } void ClearMark(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); auto marks = env->performance_marks(); if (args.Length() == 0) { marks->clear(); } else { Utf8Value name(env->isolate(), args[0]); marks->erase(*name); } } inline uint64_t GetPerformanceMark(Environment* env, std::string name) { auto marks = env->performance_marks(); auto res = marks->find(name); return res != marks->end() ? res->second : 0; } // Create a User Timing Measure. A Measure is a PerformanceEntry that // measures the duration between two distinct user timing marks void Measure(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); HandleScope scope(env->isolate()); Utf8Value name(env->isolate(), args[0]); Utf8Value startMark(env->isolate(), args[1]); Utf8Value endMark(env->isolate(), args[2]); AliasedBuffer& milestones = env->performance_state()->milestones; uint64_t startTimestamp = timeOrigin; uint64_t start = GetPerformanceMark(env, *startMark); if (start != 0) { startTimestamp = start; } else { PerformanceMilestone milestone = ToPerformanceMilestoneEnum(*startMark); if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) startTimestamp = milestones[milestone]; } uint64_t endTimestamp = GetPerformanceMark(env, *endMark); if (endTimestamp == 0) { PerformanceMilestone milestone = ToPerformanceMilestoneEnum(*endMark); if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) endTimestamp = milestones[milestone]; } if (endTimestamp < startTimestamp) endTimestamp = startTimestamp; TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( TRACING_CATEGORY_NODE2(perf, usertiming), *name, *name, startTimestamp / 1000); TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( TRACING_CATEGORY_NODE2(perf, usertiming), *name, *name, endTimestamp / 1000); PerformanceEntry entry(env, *name, "measure", startTimestamp, endTimestamp); Local obj = entry.ToObject(); PerformanceEntry::Notify(env, entry.kind(), obj); args.GetReturnValue().Set(obj); } // Allows specific Node.js lifecycle milestones to be set from JavaScript void MarkMilestone(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); Local context = env->context(); PerformanceMilestone milestone = static_cast( args[0]->Int32Value(context).ToChecked()); if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) env->performance_state()->Mark(milestone); } void SetupPerformanceObservers(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); CHECK(args[0]->IsFunction()); env->set_performance_entry_callback(args[0].As()); } // Creates a GC Performance Entry and passes it to observers void PerformanceGCCallback(Environment* env, void* ptr) { GCPerformanceEntry* entry = static_cast(ptr); HandleScope scope(env->isolate()); Local context = env->context(); AliasedBuffer& observers = env->performance_state()->observers; if (observers[NODE_PERFORMANCE_ENTRY_TYPE_GC]) { Local obj = entry->ToObject(); v8::PropertyAttribute attr = static_cast(v8::ReadOnly | v8::DontDelete); obj->DefineOwnProperty(context, env->kind_string(), Integer::New(env->isolate(), entry->gckind()), attr).FromJust(); PerformanceEntry::Notify(env, entry->kind(), obj); } delete entry; } // Marks the start of a GC cycle void MarkGarbageCollectionStart(Isolate* isolate, v8::GCType type, v8::GCCallbackFlags flags) { performance_last_gc_start_mark_ = PERFORMANCE_NOW(); performance_last_gc_type_ = type; } // Marks the end of a GC cycle void MarkGarbageCollectionEnd(Isolate* isolate, v8::GCType type, v8::GCCallbackFlags flags, void* data) { Environment* env = static_cast(data); // If no one is listening to gc performance entries, do not create them. if (!env->performance_state()->observers[NODE_PERFORMANCE_ENTRY_TYPE_GC]) return; GCPerformanceEntry* entry = new GCPerformanceEntry(env, static_cast(type), performance_last_gc_start_mark_, PERFORMANCE_NOW()); env->SetUnrefImmediate(PerformanceGCCallback, entry); } inline void SetupGarbageCollectionTracking(Environment* env) { env->isolate()->AddGCPrologueCallback(MarkGarbageCollectionStart); env->isolate()->AddGCEpilogueCallback(MarkGarbageCollectionEnd, static_cast(env)); } // Gets the name of a function inline Local GetName(Local fn) { Local val = fn->GetDebugName(); if (val.IsEmpty() || val->IsUndefined()) { Local boundFunction = fn->GetBoundFunction(); if (!boundFunction.IsEmpty() && !boundFunction->IsUndefined()) { val = GetName(boundFunction.As()); } } return val; } // Executes a wrapped Function and captures timing information, causing a // Function PerformanceEntry to be emitted to PerformanceObservers after // execution. void TimerFunctionCall(const FunctionCallbackInfo& args) { Isolate* isolate = args.GetIsolate(); HandleScope scope(isolate); Environment* env = Environment::GetCurrent(isolate); CHECK_NOT_NULL(env); // TODO(addaleax): Verify that this is correct. Local context = env->context(); Local fn = args.Data().As(); size_t count = args.Length(); size_t idx; SlicedArguments call_args(args); Utf8Value name(isolate, GetName(fn)); uint64_t start; uint64_t end; v8::TryCatch try_catch(isolate); if (args.IsConstructCall()) { start = PERFORMANCE_NOW(); TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( TRACING_CATEGORY_NODE2(perf, timerify), *name, *name, start / 1000); v8::MaybeLocal ret = fn->NewInstance(context, call_args.size(), call_args.data()); end = PERFORMANCE_NOW(); TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( TRACING_CATEGORY_NODE2(perf, timerify), *name, *name, end / 1000); if (ret.IsEmpty()) { try_catch.ReThrow(); return; } args.GetReturnValue().Set(ret.ToLocalChecked()); } else { start = PERFORMANCE_NOW(); TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( TRACING_CATEGORY_NODE2(perf, timerify), *name, *name, start / 1000); v8::MaybeLocal ret = fn->Call(context, args.This(), call_args.size(), call_args.data()); end = PERFORMANCE_NOW(); TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( TRACING_CATEGORY_NODE2(perf, timerify), *name, *name, end / 1000); if (ret.IsEmpty()) { try_catch.ReThrow(); return; } args.GetReturnValue().Set(ret.ToLocalChecked()); } AliasedBuffer& observers = env->performance_state()->observers; if (!observers[NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION]) return; PerformanceEntry entry(env, *name, "function", start, end); Local obj = entry.ToObject(); for (idx = 0; idx < count; idx++) obj->Set(context, idx, args[idx]).FromJust(); PerformanceEntry::Notify(env, entry.kind(), obj); } // Wraps a Function in a TimerFunctionCall void Timerify(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); Local context = env->context(); CHECK(args[0]->IsFunction()); CHECK(args[1]->IsNumber()); Local fn = args[0].As(); int length = args[1]->IntegerValue(context).ToChecked(); Local wrap = Function::New(context, TimerFunctionCall, fn, length).ToLocalChecked(); args.GetReturnValue().Set(wrap); } void Initialize(Local target, Local unused, Local context) { Environment* env = Environment::GetCurrent(context); Isolate* isolate = env->isolate(); performance_state* state = env->performance_state(); target->Set(context, FIXED_ONE_BYTE_STRING(isolate, "observerCounts"), state->observers.GetJSArray()).FromJust(); target->Set(context, FIXED_ONE_BYTE_STRING(isolate, "milestones"), state->milestones.GetJSArray()).FromJust(); Local performanceEntryString = FIXED_ONE_BYTE_STRING(isolate, "PerformanceEntry"); Local pe = FunctionTemplate::New(isolate); pe->SetClassName(performanceEntryString); Local fn = pe->GetFunction(context).ToLocalChecked(); target->Set(context, performanceEntryString, fn).FromJust(); env->set_performance_entry_template(fn); env->SetMethod(target, "clearMark", ClearMark); env->SetMethod(target, "mark", Mark); env->SetMethod(target, "measure", Measure); env->SetMethod(target, "markMilestone", MarkMilestone); env->SetMethod(target, "setupObservers", SetupPerformanceObservers); env->SetMethod(target, "timerify", Timerify); Local constants = Object::New(isolate); NODE_DEFINE_CONSTANT(constants, NODE_PERFORMANCE_GC_MAJOR); NODE_DEFINE_CONSTANT(constants, NODE_PERFORMANCE_GC_MINOR); NODE_DEFINE_CONSTANT(constants, NODE_PERFORMANCE_GC_INCREMENTAL); NODE_DEFINE_CONSTANT(constants, NODE_PERFORMANCE_GC_WEAKCB); #define V(name, _) \ NODE_DEFINE_HIDDEN_CONSTANT(constants, NODE_PERFORMANCE_ENTRY_TYPE_##name); NODE_PERFORMANCE_ENTRY_TYPES(V) #undef V #define V(name, _) \ NODE_DEFINE_HIDDEN_CONSTANT(constants, NODE_PERFORMANCE_MILESTONE_##name); NODE_PERFORMANCE_MILESTONES(V) #undef V v8::PropertyAttribute attr = static_cast(v8::ReadOnly | v8::DontDelete); target->DefineOwnProperty(context, FIXED_ONE_BYTE_STRING(isolate, "timeOrigin"), v8::Number::New(isolate, timeOrigin / 1e6), attr).ToChecked(); target->DefineOwnProperty( context, FIXED_ONE_BYTE_STRING(isolate, "timeOriginTimestamp"), v8::Number::New(isolate, timeOriginTimestamp / MICROS_PER_MILLIS), attr).ToChecked(); target->DefineOwnProperty(context, env->constants_string(), constants, attr).ToChecked(); SetupGarbageCollectionTracking(env); } } // namespace performance } // namespace node NODE_MODULE_CONTEXT_AWARE_INTERNAL(performance, node::performance::Initialize)