Make it possible to log distinct VM log names

RESOLVED FIXED in Firefox 50

Status

()

Core
JavaScript Engine: JIT
RESOLVED FIXED
2 years ago
2 years ago

People

(Reporter: h4writer, Assigned: h4writer)

Tracking

unspecified
mozilla50
Points:
---

Firefox Tracking Flags

(firefox50 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

(Assignee)

Description

2 years ago
It is currently possible to log VM calls. But we cannot make a distinction between which one was called. Having distinct names can attribute the cost to the specific vm call.
(Assignee)

Comment 1

2 years ago
Created attachment 8753813 [details] [diff] [review]
Patch
Assignee: nobody → hv1989
Attachment #8753813 - Flags: review?(bbouvier)
Comment on attachment 8753813 [details] [diff] [review]
Patch

Review of attachment 8753813 [details] [diff] [review]:
-----------------------------------------------------------------

Nice! I've suggested some big changes that would need new patches and new reviews; but if you don't think implementing them is worth it, then this patch as is r=me. Thank you!

::: js/src/jit/CodeGenerator.cpp
@@ +1013,5 @@
>  void
>  CodeGenerator::visitRegExp(LRegExp* lir)
>  {
>      pushArg(ImmGCPtr(lir->mir()->source()));
> +    callVM(CloneRegExpObjectInfo, lir, nullptr, TraceLogger_CloneRegExpObject);

Random idea: how do you feel about putting the tracelogger event id in the VMFunction itself? It could be another argument to FunctionInfo<>. It feels like the event id is tied to the VMFunction, not to the specific place where we're using callVM.

Or even better: have callVM create the tracelogger event id for each different VMFunction it is given, so that it is entirely transparent from the caller point of view.

Otherwise, I'd suggest switching positions of the two last arguments to callVM, as putting the tracelogger event id in the last position makes appear a lot of unexplained "nullptr" here.

::: js/src/jit/shared/CodeGenerator-shared.h
@@ +442,5 @@
>          masm.storeCallResultValue(t);
>      }
>  
> +    void callVM(const VMFunction& f, LInstruction* ins, const Register* dynStack = nullptr,
> +                TraceLoggerTextId textId = TraceLogger_VM);

Can we / should we, still pass the last argument if JS_TRACE_LOGGING is not defined?

::: js/src/vm/TraceLoggingTypes.cpp
@@ +8,5 @@
>  
>  class JSLinearString;
>  
>  uint32_t
>  TLStringToTextId(JSLinearString* str)

Out of curiosity, isn't too much time spent inside this method? I see it's only used in setupTracelogger in the debugger, so that's probably fine, but just in case...

If performance is a problem here, should we atomize the input and all the textId items, so that we can compare by pointer? Or is the cost of atomizing too high for this simple operation?

Or it'd be nice to switch on the first letter, then have a subset of "if" within each switch case, but I don't see any easy way to automate this...

Or simply use a hashmap?
Attachment #8753813 - Flags: review?(bbouvier) → review+
(Assignee)

Comment 3

2 years ago
Created attachment 8755418 [details] [diff] [review]
Patch

Updated patch.
- Add annotations to VMFunction
- Make it possible to log "const char*" out of ion.

This makes it less Tracelogger specific and in the long run make it easier to add new logging points in ion.
Attachment #8753813 - Attachment is obsolete: true
Attachment #8755418 - Flags: review?(bbouvier)
(Assignee)

Comment 4

2 years ago
(In reply to Benjamin Bouvier [:bbouvier] from comment #2)
> ::: js/src/vm/TraceLoggingTypes.cpp
> @@ +8,5 @@
> >  
> >  class JSLinearString;
> >  
> >  uint32_t
> >  TLStringToTextId(JSLinearString* str)
> 
> Out of curiosity, isn't too much time spent inside this method? I see it's
> only used in setupTracelogger in the debugger, so that's probably fine, but
> just in case...
> 
> If performance is a problem here, should we atomize the input and all the
> textId items, so that we can compare by pointer? Or is the cost of atomizing
> too high for this simple operation?
> 
> Or it'd be nice to switch on the first letter, then have a subset of "if"
> within each switch case, but I don't see any easy way to automate this...
> 
> Or simply use a hashmap?

I don't think performance of enabling and disabling the logging is important currently. As long as logging itself is low overhead and we have no overhead when tracelogging is disabled. We could indeed improve the performance here. But I don't think it is really an issue currently.
Comment on attachment 8755418 [details] [diff] [review]
Patch

Review of attachment 8755418 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks, looking better. Doesn't C++ have a way to take the real name of a function and make a const char* string out of it?

::: js/src/jit/CodeGenerator.cpp
@@ +6595,5 @@
>  typedef bool (*CompareFn)(JSContext*, MutableHandleValue, MutableHandleValue, bool*);
> +static const VMFunction EqInfo =
> +    FunctionInfo<CompareFn>(jit::LooselyEqual<true>, "LooselyEqual");
> +static const VMFunction NeInfo =
> +    FunctionInfo<CompareFn>(jit::LooselyEqual<false>, "LooselyEqual");

The name is the same for LooselyEqual<true/false>, is that fine?

@@ +6599,5 @@
> +    FunctionInfo<CompareFn>(jit::LooselyEqual<false>, "LooselyEqual");
> +static const VMFunction StrictEqInfo =
> +    FunctionInfo<CompareFn>(jit::StrictlyEqual<true>, "StrictlyEqual");
> +static const VMFunction StrictNeInfo =
> +    FunctionInfo<CompareFn>(jit::StrictlyEqual<false>, "StrictlyEqual");

ditto

@@ +9197,3 @@
>      TraceLoggerThread* logger = TraceLoggerForMainThread(cx->runtime());
> +
> +    for (uint32_t i = 0; i < patchableTLEvents_.length(); i++) {

(feel free to use a range for loop here and below)

@@ +9209,3 @@
>      }
>  
>      if (patchableTLScripts_.length() > 0) {

if (!TLFailed && ...)

@@ +9211,5 @@
>      if (patchableTLScripts_.length() > 0) {
>          MOZ_ASSERT(TraceLogTextIdEnabled(TraceLogger_Scripts));
>          TraceLoggerEvent event(logger, TraceLogger_Scripts, script);
> +        if (!ionScript->addTraceLoggerEvent(event))
> +            TLFailed = true;

Please break after this, so that we don't try to add more and more events after failing once. And then you don't need to `if (!TLFailed)` below anymore.

::: js/src/jit/IonCode.h
@@ +30,5 @@
>  class IonBuilder;
>  class IonICEntry;
>  
>  typedef Vector<JSObject*, 4, JitAllocPolicy> ObjectVector;
> +typedef Vector<TraceLoggerEvent, 4, SystemAllocPolicy> TraceLoggerEventVector;

How about having 0 items per default? This should be unused for most users.

@@ +430,5 @@
>      }
>      bool hasProfilingInstrumentation() const {
>          return hasProfilingInstrumentation_;
>      }
> +    bool addTraceLoggerEvent(TraceLoggerEvent& event) {

MOZ_MUST_USE?
Also, could TraceLogerEvent be moved instead?

::: js/src/jit/VMFunctions.h
@@ +226,5 @@
>      }
>  
>      VMFunction()
>        : wrapped(nullptr),
> +        name_("Unknown vm call"),

Here and below in this file, can you use a single static const char* for "unknown vm call"?

@@ +539,5 @@
>      static uint64_t argumentRootTypes() {
>          return BitMask<TypeToRootType, uint64_t, 3, Args...>::result;
>      }
>      explicit FunctionInfo(pf fun, PopValues extraValuesToPop = PopValues(0))
> +        : VMFunction(JS_FUNC_TO_DATA_PTR(void*, fun), "Unknown VM call", explicitArgs(),

(here)

@@ +548,5 @@
>          static_assert(MatchContext<Context>::valid, "Invalid cx type in VMFunction");
>      }
>      explicit FunctionInfo(pf fun, MaybeTailCall expectTailCall,
>                            PopValues extraValuesToPop = PopValues(0))
> +        : VMFunction(JS_FUNC_TO_DATA_PTR(void*, fun), "Unknown VM call", explicitArgs(),

(and here too)

@@ +564,5 @@
> +    {
> +        static_assert(MatchContext<Context>::valid, "Invalid cx type in VMFunction");
> +    }
> +    explicit FunctionInfo(pf fun, const char* name, MaybeTailCall expectTailCall,
> +                          PopValues extraValuesToPop = PopValues(0))

I wish C++ had positional optional arguments... In the meanwhile, and if our codebase supports delegating ctors (that's a C++11 feature, so might need tryserving all platforms first), can the supplementary ctors use one of the other FunctionInfo ctors, instead?

::: js/src/jit/shared/CodeGenerator-shared.h
@@ +111,5 @@
> +    struct PatchableTLEvent {
> +        CodeOffset offset;
> +        const char* event;
> +        PatchableTLEvent(CodeOffset offset, const char* event)
> +            : offset(offset), event(event) 

nit: trailing space

@@ +519,5 @@
>          emitTracelogTree(/* isStart =*/ false, textId);
>      }
> +    // Log an arbitrary text. The TraceloggerTextId is used to toggle the
> +    // logging on and off.
> +    // Note: the text is not copied and need to kept alive untill linking.

nit: untill => until, to kept => to be kept

::: js/src/vm/TraceLogging.cpp
@@ +1021,5 @@
>  
>      return *this;
>  }
> +
> +TraceLoggerEvent::TraceLoggerEvent(const TraceLoggerEvent& other)

If we Move memory in the call to append, I think this doesn't need to exist.
Attachment #8755418 - Flags: review?(bbouvier) → review+
(Assignee)

Comment 6

2 years ago
(In reply to Benjamin Bouvier [:bbouvier] from comment #5)
> Comment on attachment 8755418 [details] [diff] [review]
> Patch
> 
> Review of attachment 8755418 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thanks, looking better. Doesn't C++ have a way to take the real name of a
> function and make a const char* string out of it?

Really? I know about some macro magic and I tried that. But eventually removed it again. I try to only use macros if really needed. They sometimes make it very hard to understand compile errors. In this case using a string was not much worse than the macro magic. 

> ::: js/src/jit/CodeGenerator.cpp
> @@ +6595,5 @@
> >  typedef bool (*CompareFn)(JSContext*, MutableHandleValue, MutableHandleValue, bool*);
> > +static const VMFunction EqInfo =
> > +    FunctionInfo<CompareFn>(jit::LooselyEqual<true>, "LooselyEqual");
> > +static const VMFunction NeInfo =
> > +    FunctionInfo<CompareFn>(jit::LooselyEqual<false>, "LooselyEqual");
> 
> The name is the same for LooselyEqual<true/false>, is that fine?

Yeah. I don't think it matters.
 
> @@ +9211,5 @@
> >      if (patchableTLScripts_.length() > 0) {
> >          MOZ_ASSERT(TraceLogTextIdEnabled(TraceLogger_Scripts));
> >          TraceLoggerEvent event(logger, TraceLogger_Scripts, script);
> > +        if (!ionScript->addTraceLoggerEvent(event))
> > +            TLFailed = true;
> 
> Please break after this, so that we don't try to add more and more events
> after failing once. And then you don't need to `if (!TLFailed)` below
> anymore.

This is not a loop. So we can't break out of here.

> ::: js/src/jit/IonCode.h
> @@ +30,5 @@
> >  class IonBuilder;
> >  class IonICEntry;
> >  
> >  typedef Vector<JSObject*, 4, JitAllocPolicy> ObjectVector;
> > +typedef Vector<TraceLoggerEvent, 4, SystemAllocPolicy> TraceLoggerEventVector;
> 
> How about having 0 items per default? This should be unused for most users.

Definitely!

> @@ +564,5 @@
> > +    {
> > +        static_assert(MatchContext<Context>::valid, "Invalid cx type in VMFunction");
> > +    }
> > +    explicit FunctionInfo(pf fun, const char* name, MaybeTailCall expectTailCall,
> > +                          PopValues extraValuesToPop = PopValues(0))
> 
> I wish C++ had positional optional arguments... In the meanwhile, and if our
> codebase supports delegating ctors (that's a C++11 feature, so might need
> tryserving all platforms first), can the supplementary ctors use one of the
> other FunctionInfo ctors, instead?

Can I leave that for now? I don't think it will improve code much. It will be the same code, except to another constructor.

> ::: js/src/vm/TraceLogging.cpp
> @@ +1021,5 @@
> >  
> >      return *this;
> >  }
> > +
> > +TraceLoggerEvent::TraceLoggerEvent(const TraceLoggerEvent& other)
> 
> If we Move memory in the call to append, I think this doesn't need to exist.

Seems we still need :(

Comment 7

2 years ago
Pushed by hv1989@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d598b7b38612
TraceLogger: Trace the name of vm calls, r=bbouvier

Comment 8

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/d598b7b38612
Status: NEW → RESOLVED
Last Resolved: 2 years ago
status-firefox50: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla50
You need to log in before you can comment on or make changes to this bug.