1273863 - Make it possible to log distinct VM log names

Status: RESOLVED FIXED

(Core :: JavaScript Engine: JIT, defect)

Description

[Hannes Verschore [:h4writer]]

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.

Comment 1

[Hannes Verschore [:h4writer]]

Attachment: Patch

Comment 2

[Benjamin Bouvier [:bbouvier] (inactive)]

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?

Comment 3

[Hannes Verschore [:h4writer]]

Attachment: 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.

Comment 4

[Hannes Verschore [:h4writer]]

(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 5

[Benjamin Bouvier [:bbouvier] (inactive)]

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.

Comment 6

[Hannes Verschore [:h4writer]]

(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

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d598b7b38612
TraceLogger: Trace the name of vm calls, r=bbouvier

Comment 8

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d598b7b38612