Closed Bug 1339897 Opened 7 years ago Closed 7 years ago

SamplerStackFramePrintfRAII can show up in microbenchmark profiles

Categories

(Core :: Gecko Profiler, defect)

Product:
Core
Component:
Gecko Profiler
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla55
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: ehsan.akhgari, Assigned: mstange)

References

Details

Attachments

(1 file)

Bug 1339897 - Rename PROFILER_LABEL_PRINTF to PROFILER_LABEL_DYNAMIC and make it really cheap.
59 bytes, text/x-review-board-request
ehsan.akhgari
: review+
n.nethercote
: review+
Details 
See https://perfht.ml/2lkvQdf from bug 1339758.

Markus, anything we can do about this?  Can we at least call vsnprintf once here not twice?
Flags: needinfo?(mstange)
Isn't this already conditioned on the profiler_is_active() check in the ctor?
(In reply to :Ehsan Akhgari from comment #0)
> See https://perfht.ml/2lkvQdf from bug 1339758.
> 
> Markus, anything we can do about this?

Which part?
We incur nearly no overhead if the profiler is off.
We could have a separate feature for "labels with overhead" that's on by default when profiling but can be turned off.

> Can we at least call vsnprintf once here not twice?

We already do string concatenation in the macro, between two literal strings. If we could consider the format string as a literal, then we could create the final format string in the macro and only have one vsnprintf call.

name_space "::" info " " formatString

There is one place that has a dynamic format string, and that's this one:

  PROFILER_LABEL_PRINTF("ElementRestyler", "ComputeStyleChangeFor",
                        js::ProfileEntry::Category::CSS,
                        content ? "Element: %s" : "%s",
                        content ? localDescriptor.get() : "");

I'm going to change that to

  PROFILER_LABEL_PRINTF("ElementRestyler", "ComputeStyleChangeFor",
                        js::ProfileEntry::Category::CSS,
                        "Element: %s",
                        content ? localDescriptor.get() : "<unknown>");

and then we can make this change.
Assignee: nobody → mstange
Status: NEW → ASSIGNED
Flags: needinfo?(mstange)
> We incur nearly no overhead if the profiler is off.

So I just measured this.  On the testcase in bug 1339758, _without_ the patch for bug 1339891 applied, so we actually reach this code, this constructor is about 4% of the time.  It's pretty much all self time; the time under profiler_is_active() (which returns false in my case) is 0.2%.

At first glance, we do profiler_call_enter() even when !profiler_is_active(), right?  Is that expected?
Oh! That is indeed the case.
Yes, it is expected, otherwise you wouldn't have pseudostack information for functions that were already on the stack when you enabled the profiler. But maybe that wouldn't be so bad for PRINTF labels.
Comment on attachment 8837751 [details]
Bug 1339897 - Rename PROFILER_LABEL_PRINTF to PROFILER_LABEL_DYNAMIC and make it really cheap.

https://reviewboard.mozilla.org/r/112778/#review114290

This is good... But not enough IMO.  :-)

PROFILER_LABEL_PRINTF really just has no reason to exist, period.  I looked at a bunch of its call sites and they all ultimately want to append a string to the profiler label, and don't need any of the fanciness of printf.  How about we delete PROFILER_LABEL_PRINTF, add PROFILER_LABEL_WITH_DESCRIPTION which takes one more const char* arg in addition to PROFILER_LABEL and appends that string to the label without any printfs?  This means that we may need to slightly change some of the consumers, for example http://searchfox.org/mozilla-central/source/layout/base/PresShell.cpp#9165 wraps the URL with parenthesis, and I'd much rather not wrap the URL and save on all of the cost of vsnprintf.

What do you think?
Attachment #8837751 - Flags: review?(ehsan) → review+
I can do one better, and only do the string concatenation at sample time instead of at label pushing time.
Comment on attachment 8837751 [details]
Bug 1339897 - Rename PROFILER_LABEL_PRINTF to PROFILER_LABEL_DYNAMIC and make it really cheap.

https://reviewboard.mozilla.org/r/112778/#review123750

::: js/public/ProfilingStack.h:43
(Diff revision 4)
>  
>      // Descriptive string of this entry.
>      const char * volatile string;
>  
> +    // An additional descriptive string of this entry.
> +    const char * volatile annotationString;

Is the increased size of ProfileEntry significant? It goes from 3 words to 4 words on 64-bit platforms. PseudoStack has a 1024-element array of these, so that's not such a big deal. Any other significant users?

::: layout/base/PresShell.cpp:6362
(Diff revision 4)
> -    js::ProfileEntry::Category::GRAPHICS, "(%s)",
> -    uri ? uri->GetSpecOrDefault().get() : "N/A");
> +  if (uri) {
> +    uriString = uri->GetSpecOrDefault();
> +  }
> +  PROFILER_LABEL_ANNOTATE("PresShell", "Paint",
> +    js::ProfileEntry::Category::GRAPHICS,
> +    uri ? uriString.get() : "N/A");

Did you have to introduce uriString here to satisfy the compiler?

::: layout/base/PresShell.cpp:9185
(Diff revision 4)
> -    js::ProfileEntry::Category::GRAPHICS, "(%s)",
> -    uri ? uri->GetSpecOrDefault().get() : "N/A");
> +  if (uri) {
> +    uriString = uri->GetSpecOrDefault();
> +  }
> +  PROFILER_LABEL_ANNOTATE("PresShell", "DoReflow",
> +    js::ProfileEntry::Category::GRAPHICS,
> +    uri ? uriString.get() : "N/A");

Ditto.

::: tools/profiler/core/platform.cpp:414
(Diff revision 4)
>      // Cast to *((void**) to pass the text data to a void*.
>      aBuffer->addTag(ProfileBufferEntry::EmbeddedString(*((void**)(&text[0]))));
>    }
>  }
>  
> +static const int SAMPLER_MAX_STRING = 128;

Add/include "LENGTH" to the name?

::: tools/profiler/core/platform.cpp:439
(Diff revision 4)
> -  if (entry.isCopyLabel()) {
> +  if (entry.isCopyLabel() || annotationString) {
> +    if (annotationString) {
> +      // Create a string that is sampleLabel + ' ' + annotationString.
> +      size_t labelLength = strlen(sampleLabel);
> +      size_t annotationLength = strlen(annotationString);
> +      if (labelLength + 1 + annotationLength < SAMPLER_MAX_STRING) {

Please use mozilla::SprintfLiteral (in mfbt/Sprintf.h) to do this! It'll be shorter and safer. (Note that it always adds a terminating null char.)

::: tools/profiler/core/platform.cpp:2894
(Diff revision 4)
> +      *output++ = ' ';
> +      strcpy(output, annotation);
> +      output += annotationLength;
> +    } else {
> +      // Only put the label into output.
> +      size_t labelLength = strlen(label);

Move labelLength outside this block.

::: tools/profiler/public/GeckoProfiler.h:107
(Diff revision 4)
>  
> -// Insert a RAII in this scope to active a pseudo label. Any samples collected
> -// in this scope will contain this annotation. For dynamic strings use
> -// PROFILER_LABEL_PRINTF. Arguments must be string literals.
> +// Insert an RAII object in this scope to enter a pseudo stack frame. Any
> +// samples collected in this scope will contain this label in their pseudo
> +// stack. The name_space and info arguments must be string literals.
> +// Use PROFILER_LABEL_ANNOTATE if you want to add additional / dynamic
> +// information to the pseudo stack frame.

I wonder if _ADDITIONAL or _EXTRA or _DYNAMIC would be a better suffix than _ANNOTATE. Not sure, I'll let you decide.

::: tools/profiler/public/GeckoProfiler.h:124
(Diff revision 4)
> +// buffer, instead of just storing a pointer to a string literal.
> +// Use this macro to annotate functions with custom information such as URL
> +// for the resource being decoded or the size of the paint.
> +// The string buffer that |str| points to must live for the entire duration of
> +// this scope! The RAII object only stores a pointer to str, it does not copy
> +// the string data. The copy only happens during sampling.

This comment is a mix of good and bad. It's good that it contains all the relevant lifetime information, but it's bad that it's presented in a confusing way. Specifically, the comments mentions copying, then later mentions just holding a pointer, then again mentions copying. I can see why, but I think it could be rewritten to be clearer.

::: tools/profiler/public/GeckoProfiler.h:499
(Diff revision 4)
>  };
>  
> -static const int SAMPLER_MAX_STRING = 128;
>  class MOZ_RAII SamplerStackFramePrintfRAII {
>  public:
> -  // we only copy the strings at save time, so to take multiple parameters we'd need to copy them then.
> +  SamplerStackFramePrintfRAII(const char* aInfo,

Please change this class's name to not include "Printf". It should probably contain "Annotate" or "Annotation" instead, to match PROFILER_LABEL_ANNOTATE. (Or whatever suffix you decide on, if you change away from ANNOTATE.)
Attachment #8837751 - Flags: review?(n.nethercote) → review+
Comment on attachment 8837751 [details]
Bug 1339897 - Rename PROFILER_LABEL_PRINTF to PROFILER_LABEL_DYNAMIC and make it really cheap.

https://reviewboard.mozilla.org/r/112778/#review123750

> Is the increased size of ProfileEntry significant? It goes from 3 words to 4 words on 64-bit platforms. PseudoStack has a 1024-element array of these, so that's not such a big deal. Any other significant users?

I'm not aware of any other significant users. The only potential problem I can see with this is that walking the pseudo stack becomes a little slower. I haven't tested the perf impact of this.

> Did you have to introduce uriString here to satisfy the compiler?

Unfortunately not. I introduced uriString to satisfy the requirement that the string outlasts the lifetime of the SamplerStackFramePrintfRAII object. I don't think I can express this requirement to the compiler.

> Add/include "LENGTH" to the name?

ok

> Please use mozilla::SprintfLiteral (in mfbt/Sprintf.h) to do this! It'll be shorter and safer. (Note that it always adds a terminating null char.)

Oh, nice! I didn't know about that.

> I wonder if _ADDITIONAL or _EXTRA or _DYNAMIC would be a better suffix than _ANNOTATE. Not sure, I'll let you decide.

I'd be happy with _DYNAMIC but I don't know what I'd call the extra argument. aDynamicString? I'll keep _ANNOTATE for now.
Comment on attachment 8837751 [details]
Bug 1339897 - Rename PROFILER_LABEL_PRINTF to PROFILER_LABEL_DYNAMIC and make it really cheap.

https://reviewboard.mozilla.org/r/112778/#review123750

> This comment is a mix of good and bad. It's good that it contains all the relevant lifetime information, but it's bad that it's presented in a confusing way. Specifically, the comments mentions copying, then later mentions just holding a pointer, then again mentions copying. I can see why, but I think it could be rewritten to be clearer.

I rewrote this comment. I hope it's clearer now.
> > Did you have to introduce uriString here to satisfy the compiler?
> 
> Unfortunately not. I introduced uriString to satisfy the requirement that
> the string outlasts the lifetime of the SamplerStackFramePrintfRAII object.
> I don't think I can express this requirement to the compiler.

Is it worth a comment?

> > I wonder if _ADDITIONAL or _EXTRA or _DYNAMIC would be a better suffix than _ANNOTATE. Not sure, I'll let you decide.
> 
> I'd be happy with _DYNAMIC but I don't know what I'd call the extra
> argument. aDynamicString? I'll keep _ANNOTATE for now.

aDynamicString or aDynamic seems fine.
(In reply to Nicholas Nethercote [:njn] from comment #16)
> > > Did you have to introduce uriString here to satisfy the compiler?
> > 
> > Unfortunately not. I introduced uriString to satisfy the requirement that
> > the string outlasts the lifetime of the SamplerStackFramePrintfRAII object.
> > I don't think I can express this requirement to the compiler.
> 
> Is it worth a comment?

At the callsites? Maybe. Do you think so?
Actually, I'm going to fix this by Move()ing nsStrings into the SamplerStackFrameAnnotateRAII. That'll be harder to get wrong and require fewer comments.
Comment on attachment 8837751 [details]
Bug 1339897 - Rename PROFILER_LABEL_PRINTF to PROFILER_LABEL_DYNAMIC and make it really cheap.

https://reviewboard.mozilla.org/r/112778/#review125130

::: js/public/ProfilingStack.h:40
(Diff revisions 5 - 6)
>      // if a sample were taken it would be examining bogus information.
>      //
>      // A ProfileEntry represents both a C++ profile entry and a JS one.
>  
>      // Descriptive string of this entry.
>      const char * volatile string;

Does this string have to be static to be safe? If so, the comment should mention it. And then the comment on dynamicString should say that it doesn't have to be static.
Comment on attachment 8837751 [details]
Bug 1339897 - Rename PROFILER_LABEL_PRINTF to PROFILER_LABEL_DYNAMIC and make it really cheap.

https://reviewboard.mozilla.org/r/112778/#review125130

> Does this string have to be static to be safe? If so, the comment should mention it. And then the comment on dynamicString should say that it doesn't have to be static.

It's worse than that: it can be either, but if it's not static, then the isCopyLabel() must return true. I will tweak the comment.
And it looks like the comment for the FRAME_LABEL_COPY flag is reversed :( So I'll fix that one, too.
Pushed by mstange@themasta.com:
https://hg.mozilla.org/integration/autoland/rev/5c233ca5e063
Rename PROFILER_LABEL_PRINTF to PROFILER_LABEL_DYNAMIC and make it really cheap. r=Ehsan,njn
https://hg.mozilla.org/mozilla-central/rev/5c233ca5e063
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Depends on: 1351920
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: