729182 - Implement visual event tracer

Status: RESOLVED FIXED

(Core :: Networking, enhancement)

Description

[Honza Bambas (:mayhemer)]

I decided to implement a profiler (on level of C++) that will output a pretty visual timeline of per-thread events.  The goal is to have a tool to easily identify latencies and mainly quickly see the cause of them.

I have so far started to write a code purposed to publish a method Profiler::Mark() with some arguments that will write thread+time+event tupels to a log file.

The visual part (not yet implemented) will take the log file and display a nice timeline where you can search for e.g. a URL load and track all the events the load has made on all threads in the application, where it gets stuck waiting on a lock acquisitions or where events are pending a long time in event queues and easily see what is blocking it or what we can simply do better.


Reporting initially in the Networking component, since in this stage this is mainly purposed for optimization of the networking code.

Comment 1

[Honza Bambas (:mayhemer)]

Attachment: wip1

Outputs a json file with records of events.  See changes to netwerk/ for examples of how the prifiler API is used for monitoring cache lock wait/enter/leave and async open cache entry timing.

The log file path in Profiler.cpp is hardcoded for my local test server (coming on)...  update it if you want to test this patch your self.

Comment 2

[Honza Bambas (:mayhemer)]

Attachment: visualization web server content WIP (!) 1

Based on SIMILE Timeline.  Also contains an example log (cached www.cnn.com load in a debug build).  

Just copy the files somewhere and run:
/path-to/profiler/index.html?logs/profiler.txt

Each timeline you will see is dedicated to a single thread.


This is a preview WIP, so please be gentle :) There's a loooot of stuff to update:
- thread names are not displayed on timeline bands (need to figure out how to do that)
- bubble should contain more and better formatted information
- filtering of events and highlighting
- probably zooming and some kind of cursor and event boundary highlight across all threads on its selection

Comment 3

[Honza Bambas (:mayhemer)]

Attachment: ...and a little tasting screenshot (of WIP1)

Comment 4

[Honza Bambas (:mayhemer)]

Attachment: part1 v1 - xpcom and the core profiler changes

Comment 5

[Honza Bambas (:mayhemer)]

Attachment: part2 v1 - some profiler instrumentation for http

Comment 6

[Honza Bambas (:mayhemer)]

Attachment: part3 v1 - some profiler instrumentation for dns

Comment 7

[Honza Bambas (:mayhemer)]

Attachment: part4 v1 - some profiler instrumentation for cache

Comment 8

[Honza Bambas (:mayhemer)]

Attachment: part5 v1 - some profiler instrumentation for content event manager

Comment 9

[Honza Bambas (:mayhemer)]

Attachment: part6 v1 - some profiler instrumentation for docshell

Comment 10

[Honza Bambas (:mayhemer)]

Attachment: [FOR REFERENCE] all patches (1-6) merged

Comment 11

[Honza Bambas (:mayhemer)]

Attachment: Web content for visualization of the produced log

Comment 12

[Honza Bambas (:mayhemer)]

Attachment: Appetieser v2 ;)

Comment 13

[Honza Bambas (:mayhemer)]

To make this all work:
- apply https://bugzilla.mozilla.org/attachment.cgi?id=603566 from bug 720778
- apply the patches or the single merged one
- make an optimized build with ac_add_options --enable-profiling
- export MOZ_PROFILING_FILE=/path/to/log/file in your env
- run firefox with just a single or two pages tops (produced log may go extremely large otherwise)
- open file:///profiling-visuliser/index.html?/path/to/log/file

Comment 14

[Honza Bambas (:mayhemer)]

Attachment: [FOR REFERENCE] all patches (1-6) merged, this applies on m-c

I had some patches applied locally.  This one applies cleanly on current m-c.

Comment 15

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 603562 [details] [diff] [review]
part6 v1 - some profiler instrumentation for docshell

Is there any way to avoid the GetSpec when the profiler is not running?  That call can be pretty expensive....

Comment 16

[Honza Bambas (:mayhemer)]

(In reply to Boris Zbarsky (:bz) from comment #15)
> Comment on attachment 603562 [details] [diff] [review]
> part6 v1 - some profiler instrumentation for docshell
> 
> Is there any way to avoid the GetSpec when the profiler is not running? 
> That call can be pretty expensive....

Sure, that code has to be under #ifdef MOZ_PROFILING (as in other patches, here I forgot to add it).

Comment 17

[Boris Zbarsky [:bzbarsky]]

Oh, it's under MOZ_PROFILING.  Will that option be off for release builds?

Comment 18

[Honza Bambas (:mayhemer)]

(In reply to Boris Zbarsky (:bz) from comment #17)
> Oh, it's under MOZ_PROFILING.  Will that option be off for release builds?

It's controlled with --enable-profiling, that is by default disabled.

How would we produce profiling enabled build is a question, as well as it is a question if we would do that at all.  This may be limited to developers' local builds only.

Comment 19

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 603562 [details] [diff] [review]
part6 v1 - some profiler instrumentation for docshell

Ah, this is --enable-profiling.  We don't want to condition expensive operations on that, since that will mess with the profiling results.

Comment 20

[Benoit Girard (:BenWa)]

Looks interesting. I would be interested in doing a mashup of the timeline collected here with the stack profiling from the gecko profiler.

Comment 21

[Honza Bambas (:mayhemer)]

(In reply to Boris Zbarsky (:bz) from comment #19)
> Comment on attachment 603562 [details] [diff] [review]
> part6 v1 - some profiler instrumentation for docshell
> 
> Ah, this is --enable-profiling.  We don't want to condition expensive
> operations on that, since that will mess with the profiling results.

OK, what do you suggest?  Maybe calling this whole think a "profiler" is not the best chosen.  The timeline is for exposing relations and interactions between events that get scheduled, wait, then get executed.  It is not exactly a precise profiling tool as you may know it.

Comment 22

[Boris Zbarsky [:bzbarsky]]

--enable-profiling is enabled on our "profiling branch" builds and on local developer machines, and the expectation is that flipping that switch does NOT change performance characteristics other than by including frame pointers.

Is the intent for timeline information to be gathered all the time?  Or is there something that starts/stops the information-gathering?

Comment 23

[Honza Bambas (:mayhemer)]

(In reply to Boris Zbarsky (:bz) from comment #22)
> --enable-profiling is enabled on our "profiling branch" builds and on local
> developer machines, and the expectation is that flipping that switch does
> NOT change performance characteristics other than by including frame
> pointers.

Ah!  I was hoping not to interact with anything existing but I did.

I then need a different name for the option and maybe also for the tool completely.

> 
> Is the intent for timeline information to be gathered all the time?  Or is
> there something that starts/stops the information-gathering?

This version of the patch gathers all the time.  We may change it, though, but I think it is more a followup feature.

Comment 24

[Honza Bambas (:mayhemer)]

(In reply to Boris Zbarsky (:bz) from comment #22)
> --enable-profiling is enabled on our "profiling branch" builds and on local

I rename the option to --enable-visual-profiling and the C macro to MOZ_VISUAL_PROFILING.

Boris, do you think it is appropriate naming?

Comment 25

[Honza Bambas (:mayhemer)]

A real-life instance of the visualizer (may be slower on slower machines):

http://www.janbambas.cz/moz/profiler/?logs/profiler.txt

profiler.txt is a run of a saved session with a single tab edition.cnn.com loaded in a Firefox m-c optimized build (not PGO'ed one) on a fast win7 machine.

For instance, there is clearly visible that opening a cache entry on the cache thread is actually instant, but it takes from 30ms to 220ms+ for the OnCacheEntryAvailable callback to get fired back on the main thread.  That is a big wasting.

Comment 26

[Honza Bambas (:mayhemer)]

Attachment: part1 v2 - xpcom and the core profiler changes

- changes the build option to --enable-visual-profiling and the C macro to MOZ_VISUAL_PROFILING

Comment 27

[Honza Bambas (:mayhemer)]

Attachment: part2 v2 - some profiler instrumentation for http

- updated to reflect the C macro name change

Comment 28

[Honza Bambas (:mayhemer)]

Attachment: part6 v2 - some profiler instrumentation for docshell

- reflects the change in the C macro name

Comment 29

[Honza Bambas (:mayhemer)]

Attachment: [FOR REFERENCE] all patches (1-6) merged

Comment 30

[Honza Bambas (:mayhemer)]

I forgot to add an explicit dep on bug 720778.

Comment 31

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 603953 [details] [diff] [review]
part6 v2 - some profiler instrumentation for docshell

Yeah, this is better.

Comment 32

[Benjamin Smedberg]

Comment on attachment 603951 [details] [diff] [review]
part1 v2 - xpcom and the core profiler changes

> dnl ========================================================
>+dnl = Disable runtime visual profiling logger
>+dnl ========================================================
>+MOZ_ARG_DISABLE_BOOL(logging,
>+[  --disable-visual-profiling       Disable profiling facilities],

This seems leftover: you presumably want MOZ_ARG_DISABLE_BOOL(visual-profiling) right? But don't we want visual profiling off by default, and wouldn't this instead be MOZ_ARG_ENABLE_BOOL? The default config should match release configs as much as possible.

>+    NS_DISABLE_VISUAL_PROFILING=1,
>+    NS_DISABLE_VISUAL_PROFILING= )
>+if test "$NS_DISABLE_VISUAL_PROFILING"; then
>+    AC_DEFINE(NS_DISABLE_VISUAL_PROFILING)

There's no reason to define this, you don't use it anywhere and you can just use #ifndef MOZ_VISUAL_PROFILING as a condition instead.

>diff --git a/xpcom/base/Profiler.cpp b/xpcom/base/Profiler.cpp

>+// State and control variables
>+bool gInitialized = false;
>+bool gStopFlushingThread = false;
>+PRThread * gFlushingThread = nsnull;
>+PRUintn gThreadPrivateIndex;
>+mozilla::TimeStamp gProfilerStart;

It should be documented which of these variables are protected by gMonitor and/or on which threads they can be modified.

>diff --git a/xpcom/base/Profiler.h b/xpcom/base/Profiler.h

>+#ifdef MOZ_VISUAL_PROFILING


I really think all these macros need at least basic in-tree documentation. So do the class methods below. Also our standard is that all Mozilla macros should start with MOZ_ or NS_ (MOZ_ for new macros, I think).

>+namespace mozilla {
>+
>+class Profiler

This isn't a class, it's a collection of static methods. I think we should be using a mozilla::Profiler namespace for these as a style decision, instead of a class declaration.

>+class AutoProfiler

Needs docs. From the name this would appear to be used as a stack variable only, in which case please mark it with NS_STACK_CLASS.

Comment 33

[Steve Workman [:sworkman] (INACTIVE)]

Comment on attachment 603556 [details] [diff] [review]
part3 v1 - some profiler instrumentation for dns

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

Thanks for doing this; always good to have more data.

FYI, I looked through nsHTMLDNSPrefetch to see if it would be useful to have profile data there as well.  There is no lock, but there is an enqeue/dequeue.  However, the dequeue waits on the page load and/or a 2sec timer, neither of which we own the code for.  I don't think this is super-high priority; it might be interesting to see just how long we do wait until firing off prefetch requests, but apart from that, the code is pretty simple, so probably ok to ignore it.

::: netwerk/dns/nsDNSService2.cpp
@@ -605,3 @@
>      PRUint16 af = GetAFForLookup(*hostPtr, flags);
>  
>      nsDNSAsyncRequest *req =

Is it worthwhile adding nsDNSService::Resolve?  It seems to only be used by SOCKS proxy ...

::: netwerk/dns/nsHostResolver.cpp
@@ +213,5 @@
>      // allocated after it.
>      void *place = ::operator new(size);
>      *result = new(place) nsHostRecord(key);
> +
> +    PROFILER_NAME_OBJECT(*result, key->host);

Since these host records are reused, I'm wondering if that's ok for your data?  For example, say a host record is refreshed in the 1 min grace period: it's the same object, but another triplet of _WAITING, _EXECUTING, _DONE.  Maybe just something to be aware of.

@@ +1020,5 @@
>  #if defined(RES_RETRY_ON_FAILURE)
>          if (!ai && rs.Reset())
>              ai = PR_GetAddrInfoByName(rec->host, rec->af, flags);
>  #endif
>  

Is it useful for your purposes to add a PROFILER_MARK just after getaddrinfo finishes? That way we can see what time is spent in getaddrinfo, which is out of our control in most circumstances (excluding Android pre3.0 at present).

Comment 34

[Honza Bambas (:mayhemer)]

(In reply to Steve Workman [:sworkman] from comment #33)
> Is it worthwhile adding nsDNSService::Resolve?  It seems to only be used by
> SOCKS proxy ...

Maybe, but not for the first implementation probably.

> Since these host records are reused, I'm wondering if that's ok for your
> data?  

This would be wrong if the host name would change during lifetime of nsHostRecord object.  Is that so?

> For example, say a host record is refreshed in the 1 min grace
> period: it's the same object, but another triplet of _WAITING, _EXECUTING,
> _DONE.  Maybe just something to be aware of.

If that is just that and I understand right, then it is OK.  I don't think the triplet may overlap, I assume it will always be WAIT, EXEC, DONE, WAIT, EXEC, DONE and not intermixing.  The profiler is made to work with this.

> Is it useful for your purposes to add a PROFILER_MARK just after getaddrinfo
> finishes? That way we can see what time is spent in getaddrinfo, which is
> out of our control in most circumstances (excluding Android pre3.0 at
> present).

I was thinking of this too.  Question is if calling OnLookupComplete can happen much later after we exit from getaddrinfo.  Maybe it is worth to do it the way you suggest.  However, I was also interested in how long it takes from dispatching the callback on the host-resolver thread to actual execution on the consumer (main) thread.  The actual code will give this to you.  

We could also have a two events: one for processing nsHostRequest and one for execution of getaddrinfo for the host.  It is doable, I'll try what results it will give me.  All depends on how we want to present - the more readable and simpler the better.

Comment 35

[Steve Workman [:sworkman] (INACTIVE)]

(In reply to Honza Bambas (:mayhemer) from comment #34)
> > Since these host records are reused, I'm wondering if that's ok for your
> > data?  
> 
> This would be wrong if the host name would change during lifetime of
> nsHostRecord object.  Is that so?

No. There is no change during the lifetime.

> > For example, say a host record is refreshed in the 1 min grace
> > period: it's the same object, but another triplet of _WAITING, _EXECUTING,
> > _DONE.  Maybe just something to be aware of.
> 
> If that is just that and I understand right, then it is OK.  I don't think
> the triplet may overlap, I assume it will always be WAIT, EXEC, DONE, WAIT,
> EXEC, DONE and not intermixing.  The profiler is made to work with this.

Ok, cool.

> > Is it useful for your purposes to add a PROFILER_MARK just after getaddrinfo
> > finishes? That way we can see what time is spent in getaddrinfo, which is
> > out of our control in most circumstances (excluding Android pre3.0 at
> > present).
> 
> I was thinking of this too.  Question is if calling OnLookupComplete can
> happen much later after we exit from getaddrinfo.  Maybe it is worth to do
> it the way you suggest.  However, I was also interested in how long it takes
> from dispatching the callback on the host-resolver thread to actual
> execution on the consumer (main) thread.  The actual code will give this to
> you.  

I think I understand what you're saying but just to clarify, OnLookupComplete runs in the context of one of the host resolver threads.  I think you mean how long from the request was dispatched to the thread until processing starts (getaddrinfo) and then the result dealt with in OnLookupComplete, right?

Re adding PROFILER_MARK, it's possible there could be some times spent waiting in nsHostResolver::OnLookupComplete, because there are a couple of mutexes (one for the whole resolver and one for the record's address info).  So adding PROFILER_MARK between getaddrinfo and the mutexes could be useful to determine if we need to revisit the mutexes.  Of the top of my head, I'm wondering if a large number of prefetch requests could lock up the host resolver mutex in ::ResolveHost??
> 
> We could also have a two events: one for processing nsHostRequest and one
> for execution of getaddrinfo for the host.  It is doable, I'll try what
> results it will give me.  All depends on how we want to present - the more
> readable and simpler the better.

I'll leave it in your hands to determine what is easier to read :)

Comment 36

[Honza Bambas (:mayhemer)]

Comment on attachment 603952 [details] [diff] [review]
part2 v2 - some profiler instrumentation for http

Reassigning to Patrick.  This is not strictly urgent to review soon.

Comment 37

[Honza Bambas (:mayhemer)]

Attachment: part1 v3

- visual profiling code disabled by default
- when enabled, MOZ_VISUAL_PROFILING is defined in C
- mozilla::profiler is a namespace now
- added a lot of comments on the profiler's API

Comment 38

[Honza Bambas (:mayhemer)]

Comment on attachment 603954 [details] [diff] [review]
[FOR REFERENCE] all patches (1-6) merged

No longer applies.

Comment 39

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Comment on attachment 603560 [details] [diff] [review]
part5 v1 - some profiler instrumentation for content event manager

Sorry for taking so long to get to this.

I tend to think this probably belongs in someplace more central to event handling, probably either nsPresShell or nsViewManager.  nsEventStateManager manages event state changes (:hover, :active, etc.) but isn't really involved in all events, and it seems like this sort of thing belongs someplace where we'd expect all events to go through.

That said, I think on this topic smaug's opinion probably counts for more than mine, and you should ask him where this really belongs before proceeding, and ask him for review.

Comment 40

[Olli Pettay [:smaug][[e-mail]]]

I don't know what this profiler is trying to profile, but dbaron's comment makes probably sense :)
If you want to profile user/OS initiated events, PresShell::HandleEvent is probably the right
place.

Comment 41

[Olli Pettay [:smaug][[e-mail]]]

How is this all related to the about:jank profiling?

Comment 42

[Honza Bambas (:mayhemer)]

(In reply to Olli Pettay [:smaug] from comment #40)
> I don't know what this profiler is trying to profile, but dbaron's comment
> makes probably sense :)
> If you want to profile user/OS initiated events, PresShell::HandleEvent is
> probably the right
> place.

Thanks for an advice!

(In reply to Olli Pettay [:smaug] from comment #41)
> How is this all related to the about:jank profiling?

None.  My feature can be used as a general tool to find how timing of things looks like in "realtime".  I build it mainly for catching delays in networking operations.  You have to instrument the code, though.

(Also, I'm not sure "profiling" is the right name for this feature, but I don't have a better one atm.)

Comment 43

[Benjamin Smedberg]

Comment on attachment 615374 [details] [diff] [review]
part1 v3

This fell off my radar after the email thread, but I've reviewed the build goop around this and it looks fine. Ehsan volunteered to review the actual profiler information.

Comment 44

[Honza Bambas (:mayhemer)]

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #43)
> Comment on attachment 615374 [details] [diff] [review]
> part1 v3
> 
> This fell off my radar after the email thread, but I've reviewed the build
> goop around this and it looks fine. Ehsan volunteered to review the actual
> profiler information.

Benjamin, thank you.

Ehsan, do you have estimation on when you get to this?  If soon, I want to ping wtc on the thread-names patch (blocking this one).

Comment 45

[(no longer active)]

Comment on attachment 615374 [details] [diff] [review]
part1 v3

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

Your patch generally looks good.  A lot of the below comments are nits, and I hate to be pedantic, so please ignore them where you don't think they make sense.  :-)

But I'm minusing because I think there are a number of mistakes below, and I'd really like to look at another version of this patch.

::: configure.in
@@ +7489,5 @@
>  
>  dnl ========================================================
> +dnl = Enable runtime visual profiling logger
> +dnl ========================================================
> +MOZ_ARG_ENABLE_BOOL(visual-profiling,

OK, this is more of a nit, but I think we should get this right before this code lands.

To the best of my understanding, this is not a profiler (at least in the traditional sense), and based on the previous comments on the bug I think you agree.  How about calling it "visual event tracer" (which is what this is, as far as I can tell)?  Or perhaps some other name?  Please rename things to be consistent with the better name, for example, call this --enable-visual-event-tracer, rename Profiler.{h,cpp} to VisualEventTracer.{h,cpp}, etc.

@@ +7492,5 @@
> +dnl ========================================================
> +MOZ_ARG_ENABLE_BOOL(visual-profiling,
> +[  --enable-visual-profiling   Enable visual profiling instrumentation],
> +    MOZ_VISUAL_PROFILING=1,
> +    MOZ_VISUAL_PROFILING=)

I don't quite grok autoconf, but please make sure that this is off by default.  :-)

::: xpcom/base/Profiler.cpp
@@ +1,1 @@
> +/* -*- Mode: C++; tab-width: 40; indent-tabs-mode: nil; c-basic-offset: 4 -*- */

This will kill the people who use editors which understand this modeline.  ;-)

Please set the tab-width to 2 (in the header too).

@@ +47,5 @@
> +#include "plstr.h"  
> +
> +namespace mozilla { namespace profiler {
> +
> +namespace {

Please move the anonymous namespace out of the above namespaces.

@@ +58,5 @@
> +
> +// Record of a single event
> +class Record {
> +public:
> +  Record() : mText(nsnull), mText2(nsnull) {} 

Please initialize all of the members in the constructor.

@@ +91,5 @@
> +  static EventFilter * Build(const char * filterVar);
> +  bool EventPasses(const char * eventName);
> +private:
> +  EventFilter(const char * eventName, EventFilter * next);
> +  ~EventFilter();

So, this destructor being private means that no code will ever get a chance to delete the chain of EventFilters.  While these objects are alive throughout the runtime of the program, this is not good practice.  Please make this public, and delete it in the Shutdown method.

Also, please add MOZ_COUNT_CTOR/MOZ_COUNT_DTOR to the ctors/dtors of your helper objects so that this kind of stuff would be caught in debug builds.

@@ +109,5 @@
> +bool gStopFlushingThread = false;
> +
> +// Accessed concurently but since this flag is not functionally critical
> +// for optimization purposes is not accessed under a lock
> +bool gInitialized = false;

gInitialized means more than whether the tracer has been successfully initialized.  How about calling it gTracingEnabled or something?  Also please make it volatile.

@@ +126,5 @@
> +  mRecordsHead = new Record[kBatchSize];
> +  mRecordsTail = mRecordsHead + kBatchSize;
> +  mNextRecord = mRecordsHead;
> +
> +  mThreadNameCopy = PL_strdup(PR_GetThreadName());

Please initialize all of these in the initializer list.  Also I think making this inline would make the code a bit easier to read (since this is mostly a struct.)

@@ +132,5 @@
> +
> +RecordBatch::~RecordBatch()
> +{
> +  delete [] mRecordsHead;
> +  PL_strfree(mThreadNameCopy);

Please make this inline as well.

@@ +152,5 @@
> +  if (!gLogHead)
> +    gLogHead = threadLogPrivate;
> +  if (gLogTail)
> +    gLogTail->mNextBatch = threadLogPrivate;
> +  gLogTail = threadLogPrivate;

If I'm reading your code correctly, gLogHead and gLogTail are both either non-null or null at any time where the monitor is locked, right?  Given this, you can rewrite the second if as just |else|.

Also, I think it would help the code to be more readable if you would wrap these two in a small class, called LogList or something which provides helper methods such as AddLog(), IsEmpty(), etc.

@@ +159,5 @@
> +}
> +
> +// static
> +EventFilter *
> +EventFilter::Build(const char * filterVar)

I made a couple of mistakes while reading this code.  While the recursive nature of this method is pretty slick, it could use some documentation.  :-)

@@ +167,5 @@
> +
> +  // Copied from nspr logging code (read of NSPR_LOG_MODULES)
> +  char eventName[64];
> +  PRIntn evlen = strlen(filterVar), pos = 0, count = 0, delta = 0;
> +  count = sscanf(filterVar + pos, "%63[^,]%n",

Please document what this format string does.  Also, the |+ pos| here is redundant.

@@ +172,5 @@
> +                 eventName, &delta);
> +  if (count == 0) 
> +    return nsnull;
> +
> +  pos += delta;

s/+=/=/

@@ +174,5 @@
> +    return nsnull;
> +
> +  pos += delta;
> +
> +  count = sscanf(filterVar + pos, " , %n", &delta);

Why do you require spaces between the items in the list?  That looks unintuitive to me.

@@ +191,5 @@
> +EventFilter::~EventFilter()
> +{
> +  delete mNext;
> +  PL_strfree(mFilter);
> +}

These two methods should also be inlined I think.

@@ +216,5 @@
> +void FlushingThread(void * aArg)
> +{
> +  PRFileDesc * logFile = PR_Open(gLogFilePath, 
> +                         PR_WRONLY | PR_TRUNCATE | PR_CREATE_FILE,
> +                         644);

I'm pretty sure you meant 0644 here.

@@ +254,5 @@
> +        const char threadDelimiter[] = ",\n";
> +        rv = PR_Write(logFile, threadDelimiter, sizeof(threadDelimiter) - 1);
> +        ioError |= (rv < 0);
> +      }
> +      firstBatch = false;

Nit: please move this inside the if block.

@@ +269,5 @@
> +      for (Record * record = batch->mRecordsHead;
> +           record < batch->mNextRecord && !ioError;
> +           ++record) {
> +
> +        PRUint32 type = record->mType & 0xffffUL;

Why is this and needed?

@@ +270,5 @@
> +           record < batch->mNextRecord && !ioError;
> +           ++record) {
> +
> +        PRUint32 type = record->mType & 0xffffUL;
> +        PRUint32 flags = record->mType >> 16;

I don't understand why this bitshift is performed here.

@@ +298,5 @@
> +
> +  const char logTail[] = "]}\n";
> +  PR_Write(logFile, logTail, sizeof(logTail) - 1);
> +
> +  PR_Close(logFile);

I think you should do something sensible here if ioError is true.  That would mean that the JSON file is not valid.  How about truncating the file or something?

@@ +318,5 @@
> +
> +  gProfilerStart = mozilla::TimeStamp::Now();
> +
> +  PRStatus status;
> +  status = PR_NewThreadPrivateIndex(&gThreadPrivateIndex, 

Nit: no need to declare and initialize on two lines.

@@ +336,5 @@
> +                                    PR_LOCAL_THREAD,
> +                                    PR_JOINABLE_THREAD,
> +                                    32768);
> +  if (!gFlushingThread) {
> +    gInitialized = false;

How about just setting gInitialized after here?

@@ +353,5 @@
> +{
> +#ifdef MOZ_VISUAL_PROFILING
> +  MOZ_PROFILER_MARK(gFlushingThread, "Profiling End");
> +
> +  // This must be called after all other threads had been shutted down 

s/shutted/shut/

::: xpcom/base/Profiler.h
@@ +59,5 @@
> +#include "mozilla/GuardObjects.h"
> +
> +#ifdef MOZ_VISUAL_PROFILING
> +
> +// Bound an object instance, usually |this|, to a name, usually URL or 

Nit: s/Bound/Bind/.

@@ +111,5 @@
> +// event details.
> +// NOTE: when the event duration is extremely short, like 1ms, it will convert
> +// to an event w/o a duration - the same as MOZ_PROFILER_MARK would be used.
> +#define MOZ_PROFILER_DONE(instance, name) \
> +  mozilla::profiler::Mark(mozilla::profiler::eDone, instance, name)

It will be very helpful to give an example of an event which needs the above three phases in the comments.

@@ +122,5 @@
> +  mozilla::profiler::Mark(mozilla::profiler::eWait | mozilla::profiler::eThreadConcurrent, instance, name)
> +#define MOZ_PROFILER_EXECUTING_THREADSAFE(instance, name) \
> +  mozilla::profiler::Mark(mozilla::profiler::eExec | mozilla::profiler::eThreadConcurrent, instance, name)
> +#define MOZ_PROFILER_DONE_THREASAFE(instance, name) \
> +  mozilla::profiler::Mark(mozilla::profiler::eDone | mozilla::profiler::eThreadConcurrent, instance, name)

Does it make sense to have a _COMPOUND variant of all of these macros?

@@ +141,5 @@
> +
> +#endif
> +
> +
> +namespace mozilla { namespace profiler {

Nit: please add a line break.

@@ +148,5 @@
> +void Init();
> +
> +// Shuts the profiler engine down and closes the log file, called 
> +// automatically during XPCOM shutdown.
> +void Shutdown();

This is something that you might want to address in future patches, but I think a much better model for using this is to make it possible to toggle the profiler this at runtime.  This doesn't necessarily make it unnecessary to call Init and Shutdown the way you currently do, but you might need to adjust the comments here.

@@ +180,5 @@
> +// @param aText2
> +//    Optional second part of the instnace name, or event name.
> +//    Event filtering does apply only to the first part (aText).
> +void Mark(PRUint32 aType, void * aItem, 
> +          const char * aText, const char * aText2 = 0);

Please rename aText and aText2 to something like aName and aDescription.

@@ +202,5 @@
> +               PRUint32 aTypeOff, // MarkType marked in destructor
> +               const char * aName, 
> +               const char * aName2 = 0 
> +               MOZ_GUARD_OBJECT_NOTIFIER_PARAM)
> +    : mThis(aThis)

"instance" seems like a better name here than "this".

Comment 46

[Honza Bambas (:mayhemer)]

Thanks for the review!

(In reply to Ehsan Akhgari [:ehsan] from comment #45)
> This will kill the people who use editors which understand this modeline. 
> ;-)
> 
> Please set the tab-width to 2 (in the header too).

I rather removed them completely.

> gInitialized means more than whether the tracer has been successfully
> initialized.  How about calling it gTracingEnabled or something?  Also
> please make it volatile.

I think "initialized" is better.  The tracer cannot be turned off and on at runtime, the events wouldn't be consistent.

> Also, I think it would help the code to be more readable if you would wrap
> these two in a small class, called LogList or something which provides
> helper methods such as AddLog(), IsEmpty(), etc.

Not necessary IMO.

> Why do you require spaces between the items in the list?  That looks
> unintuitive to me.

Why not to?  Programmers can make a mistake by adding a space.  Rather allow it.

> I'm pretty sure you meant 0644 here.

Thanks for this catch! :)

> Nit: please move this inside the if block.

Are you sure?

> I think you should do something sensible here if ioError is true.  That
> would mean that the JSON file is not valid.  How about truncating the file
> or something?

I'm deleting the file.

> Does it make sense to have a _COMPOUND variant of all of these macros?

Not much.  But when somebody needs them, then let him just add it.

> > +namespace mozilla { namespace profiler {
> 
> Nit: please add a line break.

That would be against the styling rules.  (I'd prefer your suggestion, but don't tell anyone ;))

> This is something that you might want to address in future patches, but I
> think a much better model for using this is to make it possible to toggle
> the profiler this at runtime.  This doesn't necessarily make it unnecessary
> to call Init and Shutdown the way you currently do, but you might need to
> adjust the comments here.

I'm not sure that is even possible.  But I have to think of this.  I believe it will become a request soon.

> Please rename aText and aText2 to something like aName and aDescription.

No.  It's not a "name" and "description".  It's a first part of the text and a second part of the text of an event name or an instance resource identifier.


Patch will come later.

Comment 47

[(no longer active)]

(In reply to Honza Bambas (:mayhemer) from comment #46)
> > Nit: please move this inside the if block.
> 
> Are you sure?

Hrm, no, my bad.  Please ignore this.

The rest of the comments are fine by me!

Comment 48

[Honza Bambas (:mayhemer)]

(In reply to Ehsan Akhgari [:ehsan] from comment #45)
> Please move the anonymous namespace out of the above namespaces.

No.  The code in it is using and is bound to mozilla::eventtracer namespace.  I'll leave it inside.  We already use these construction in other modules.  I don't see a problem with it.

Comment 49

[Honza Bambas (:mayhemer)]

Attachment: part1 v4

Comment 50

[(no longer active)]

Comment on attachment 624362 [details] [diff] [review]
part1 v4

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

A lot of the code in VisualEventTracer.cpp is not protected by the MOZ_VISUAL_EVENT_TRACER macro.  While a good linker should drop all of these symbols because they're not used anywhere, I wonder if you have made sure that a build without --enable-visual-event-tracer does indeed get no code from the symbols in that file (except for perhaps the empty stubs)?

::: configure.in
@@ +7562,5 @@
>  dnl ========================================================
> +dnl = Enable runtime visual profiling logger
> +dnl ========================================================
> +MOZ_ARG_ENABLE_BOOL(visual-profiling,
> +[  --enable-visual-event-tracer   Enable visual event tracer instrumentation],

The variable name passed to MOZ_ARG_ENABLE_BOOL is different with the documentation string here...

Comment 51

[Patrick McManus [:mcmanus]]

Comment on attachment 603952 [details] [diff] [review]
part2 v2 - some profiler instrumentation for http

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

First - I'm sincerely sorry about the delay.

I wanted to play around with this code (I'm excited about it!) but couldn't get the bug 720778 dependency to compile. Looking forward to seeing it in action.

So this r? is from my understanding of the code and comments, I'm sorry if I've misunderstood anything. However I'm comfortable that it is a good code addition and it doesn't negatively impact anything in a non-profiling build so that right there is enough for a r+ to keep the work moving.

::: netwerk/base/src/nsSocketTransport2.cpp
@@ +2043,5 @@
>  {
>      // flag host lookup complete for the benefit of the ResolveHost method.
>      mResolving = false;
>  
> +    PROFILER_WAITING(this, "TCP connect");

shouldn't the wait time potentially cover the dns lookup time too (so we can see which tcp lookups are blocked on dns?)

::: netwerk/protocol/http/nsHttpConnection.cpp
@@ +333,5 @@
>      LOG(("nsHttpConnection::Activate [this=%x trans=%x caps=%x]\n",
>           this, trans, caps));
>  
> +    PROFILER_EXECUTING(trans, "nsHttpTransaction");
> +

that trans is a _A_trans .. is that ok?

::: netwerk/protocol/http/nsHttpTransaction.cpp
@@ +163,5 @@
>                          nsIAsyncInputStream **responseBody)
>  {
> +    PROFILER_COMPOUND_NAME(this, requestHead->PeekHeader(nsHttp::Host), 
> +                           requestHead->RequestURI().BeginReading());
> +  

maybe a comment indicating that the PROFILER_WAITING for this object is happening in nshttpchannel? I spent a while trying to find it.

Comment 52

[Honza Bambas (:mayhemer)]

Attachment: part1 v5 - the core

Thanks everybody for all reviews!

This new feature is about to land soon after update of m-c to NSPR 4.9.1 and landing of patch from bug 720778 that has also been r+'ed.

Comment 53

[(not currently active) Ted Mielczarek]

FYI, m-c has been updated to an NSPR 4.9.1 beta tag, but I'm not sure if it included everything you want.

Comment 54

[Honza Bambas (:mayhemer)]

Attachment: part1 v5 - the core (as landed)

https://hg.mozilla.org/integration/mozilla-inbound/rev/22796d93c42e

Comment 55

[Honza Bambas (:mayhemer)]

(In reply to Patrick McManus [:mcmanus] from comment #51)
> Comment on attachment 603952 [details] [diff] [review]

> shouldn't the wait time potentially cover the dns lookup time too (so we can
> see which tcp lookups are blocked on dns?)

There are probes for DNS it self in a different patch.

> that trans is a _A_trans .. is that ok?

Will check before landing, it used to work for me, but worth to double check.  Thanks.

Comment 56

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/mozilla-central/rev/22796d93c42e

Comment 57

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

Comment on attachment 632307 [details] [diff] [review]
part1 v5 - the core (as landed)

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

::: xpcom/base/VisualEventTracer.cpp
@@ +1,2 @@
> +/* ***** BEGIN LICENSE BLOCK *****
> + * Version: MPL 1.1/GPL 2.0/LGPL 2.1

Tut tut, use MPL2 please.

Comment 58

[Honza Bambas (:mayhemer)]

Attachment: part2 v3 - some profiler instrumentation for http

- unbitrotted
- changed some transaction probes according also the review comments
- added probes for case a channel redirects

According more changes I rather re-request the review.

Comment 59

[Honza Bambas (:mayhemer)]

Attachment: part3 v2 - some profiler instrumentation for dns

- unbitrotted

Comment 60

[Honza Bambas (:mayhemer)]

Attachment: part4 v2 - some profiler instrumentation for cache

- unbitrotted
- I didn't have any time to add the probes we were tacking about, Michal, but this is the minimum I would like to land asap

Other probes in followup patches, I need to think a bit before I add them.

Comment 61

[Honza Bambas (:mayhemer)]

Attachment: part6 v3 - some profiler instrumentation for docshell

- unbitrotted

Comment 62

[Honza Bambas (:mayhemer)]

Attachment: Web content for visualization of the produced log

Completely self contained.

Comment 63

[Michal Novotny [:michal]]

Comment on attachment 635130 [details] [diff] [review]
part4 v2 - some profiler instrumentation for cache

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

::: netwerk/cache/nsCacheService.cpp
@@ +1732,5 @@
>  nsCacheService::NotifyListener(nsCacheRequest *          request,
>                                 nsICacheEntryDescriptor * descriptor,
>                                 nsCacheAccessMode         accessGranted,
> +                               nsresult                  status,
> +                               nsACString              * keyForLogging)

Why don't you use the key from request here?

::: netwerk/cache/nsDiskCacheDevice.cpp
@@ +46,5 @@
>  
>  #include "mozilla/FunctionTimer.h"
>  #include "nsThreadUtils.h"
>  #include "mozilla/Telemetry.h"
> +#include "mozilla/VisualEventTracer.h"

Event tracer isn't used in this file.

::: netwerk/cache/nsDiskCacheMap.cpp
@@ +670,5 @@
>  {
>      CACHE_LOG_DEBUG(("CACHE: ReadDiskCacheEntry [%x]\n", record->HashNumber()));
>  
> +    //::mozilla::eventtracer::AutoEventTracer readDiskCacheEntry(
> +    //    ?, ::mozilla::eventtracer::eExec, ::mozilla::eventtracer::eDone, "ReadDiskCacheEntry");

Either remove it or uncomment it.

Comment 64

[Honza Bambas (:mayhemer)]

(In reply to Michal Novotny (:michal) from comment #63)
> Comment on attachment 635130 [details] [diff] [review]
> part4 v2 - some profiler instrumentation for cache

> Why don't you use the key from request here?

Because it is already freed (null) in the request.  There is no other way to access the key, at least AFAIK.

> > +    //::mozilla::eventtracer::AutoEventTracer readDiskCacheEntry(
> > +    //    ?, ::mozilla::eventtracer::eExec, ::mozilla::eventtracer::eDone, "ReadDiskCacheEntry");
> 
> Either remove it or uncomment it.

Ah, sorry, didn't finish this piece.  This would be very interesting probe, but at this place it's very hard to find the cache entry key to use for log, hence the '?'.  We can solve this in some other bug.

Comment 65

[Honza Bambas (:mayhemer)]

Attachment: part4 v2.1 - some profiler instrumentation for cache

Comment 66

[Michal Novotny [:michal]]

Comment on attachment 635378 [details] [diff] [review]
part4 v2.1 - some profiler instrumentation for cache

(In reply to Honza Bambas (:mayhemer) from comment #64)
> (In reply to Michal Novotny (:michal) from comment #63)
> > Comment on attachment 635130 [details] [diff] [review]
> > part4 v2 - some profiler instrumentation for cache
> 
> > Why don't you use the key from request here?
> 
> Because it is already freed (null) in the request.  There is no other way to
> access the key, at least AFAIK.

If it is freed in the request, then it should be accessible as descriptor->CacheEntry()->Key().

Comment 67

[Honza Bambas (:mayhemer)]

(In reply to Michal Novotny (:michal) from comment #66)
> If it is freed in the request, then it should be accessible as
> descriptor->CacheEntry()->Key().

 	KernelBase.dll!_DebugBreak@0()  + 0x2 bytes	
 	xul.dll!RealBreak()  Line 416	C++
 	xul.dll!Break(const char * aMsg=0x12c9f4c0)  Line 515	C++
 	xul.dll!NS_DebugBreak_P(unsigned int aSeverity=1, const char * aStr=0x0f0f8f30, const char * aExpr=0x5b7f7850, const char * aFile=0x5b7f77f8, int aLine=128)  Line 374 + 0xc bytes	C++
 	xul.dll!mozilla::BlockingResourceBase::CheckAcquire(const mozilla::CallStack & aCallContext={...})  Line 128 + 0x1f bytes	C++
 	xul.dll!mozilla::Mutex::Lock()  Line 228	C++
 	xul.dll!nsCacheService::Lock()  Line 2510	C++
 	xul.dll!nsCacheServiceAutoLock::nsCacheServiceAutoLock()  Line 320	C++
>	xul.dll!nsCacheEntryDescriptor::GetKey(nsACString_internal & result={...})  Line 83	C++
 	xul.dll!nsCacheService::NotifyListener(nsCacheRequest * request=0x0879abb0, nsICacheEntryDescriptor * descriptor=0x0f5eaed0, int accessGranted=3, unsigned int status=0)  Line 1757	C++

With:


###!!! ASSERTION: Potential deadlock detected:
Cyclical dependency starts at
Mutex : nsCacheService.mLock (currently acquired)
Cycle completed at
Mutex : nsCacheService.mLock (currently acquired)

###!!! Deadlock may happen NOW!

: 'Error', file c:/Mozilla/src/mozilla-central/_obj-browser-debug/xpcom/build/BlockingResourceBase.cpp, line 128

Comment 68

[Patrick McManus [:mcmanus]]

Comment on attachment 635113 [details] [diff] [review]
part2 v3 - some profiler instrumentation for http

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

::: netwerk/protocol/http/nsHttpConnectionMgr.cpp
@@ +18,5 @@
>  
>  #include "nsISSLSocketControl.h"
>  #include "prnetdb.h"
>  #include "mozilla/Telemetry.h"
> +#include "mozilla/VisualEventTracer.h"

this is the only diff in this file, so include is probly not needed

Comment 69

[Honza Bambas (:mayhemer)]

Comment on attachment 635113 [details] [diff] [review]
part2 v3 - some profiler instrumentation for http

https://hg.mozilla.org/integration/mozilla-inbound/rev/30a4e0cf7130

Comment 70

[Honza Bambas (:mayhemer)]

Comment on attachment 635118 [details] [diff] [review]
part3 v2 - some profiler instrumentation for dns

https://hg.mozilla.org/integration/mozilla-inbound/rev/ad2c42efbe57

Comment 71

[Honza Bambas (:mayhemer)]

Comment on attachment 635135 [details] [diff] [review]
part6 v3 - some profiler instrumentation for docshell

https://hg.mozilla.org/integration/mozilla-inbound/rev/1f07f04ec01d

Comment 72

[Ryan VanderMeulen [:RyanVM]]

http://mozillamemes.tumblr.com/post/21637966463/yes-i-have-a-condition-that-forces-me-to-insert

One of the patches was causing xpcshell failures. Since I didn't see Try results in any of the bugs, I had to backout the entire push.
https://hg.mozilla.org/integration/mozilla-inbound/rev/981ac887f6e2
https://hg.mozilla.org/integration/mozilla-inbound/rev/925562fd7d68

An example:
https://tbpl.mozilla.org/php/getParsedLog.php?id=13404043&tree=Mozilla-Inbound

TEST-INFO | /home/cltbld/talos-slave/test/build/xpcshell/tests/netwerk/test/unit/test_cacheForOfflineUse_no-store.js | running test ...
TEST-UNEXPECTED-FAIL | /home/cltbld/talos-slave/test/build/xpcshell/tests/netwerk/test/unit/test_cacheForOfflineUse_no-store.js | test failed (with xpcshell return code: 0), see following log:
>>>>>>>

TEST-INFO | (xpcshell/head.js) | test 1 pending

TEST-INFO | (xpcshell/head.js) | test 2 pending

TEST-INFO | (xpcshell/head.js) | test 2 finished

TEST-INFO | (xpcshell/head.js) | running event loop

TEST-INFO | (xpcshell/head.js) | test 2 pending
TEST-INFO | /home/cltbld/talos-slave/test/build/xpcshell/tests/netwerk/test/unit/test_cacheForOfflineUse_no-store.js | Starting test_normal

TEST-UNEXPECTED-FAIL | /home/cltbld/talos-slave/test/build/xpcshell/head.js | [Exception... "Cannot modify properties of a WrappedNative"  nsresult: "0x80570034 (NS_ERROR_XPC_CANT_MODIFY_PROP_ON_WN)"  location: "JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/tests/netwerk/test/unit/test_cacheForOfflineUse_no-store.js :: make_channel_for_offline_use :: line 21"  data: no] - See following stack:
JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/head.js :: do_throw :: line 451
JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/head.js :: _run_next_test :: line 899
JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/head.js :: <TOP_LEVEL> :: line 418

TEST-INFO | (xpcshell/head.js) | exiting test

TEST-INFO | (xpcshell/head.js) | test 2 finished
<<<<<<<

Comment 73

[Robert O'Callahan (:roc) (email my personal email if necessary)]

These PROFILER_MARK and MOZ_EVENT_TRACER macros really need to be integrated with SPS instrumentation. I would go so far as to suggest that this work should not land until that integration is done.

Comment 74

[Honza Bambas (:mayhemer)]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #73)
> These PROFILER_MARK and MOZ_EVENT_TRACER macros really need to be integrated
> with SPS instrumentation. I would go so far as to suggest that this work
> should not land until that integration is done.

I have no problem with that.  Also because I would like to land all the remaining instrumentation patches altogether and there are still some pending reviews/work (Michal?).

Robert, can you please be more specific on what you actually want me to do?  not sure what SPS instrumentation is.  Thanks.

Comment 75

[Robert O'Callahan (:roc) (email my personal email if necessary)]

The SPS profiler has some macros to annotate its performance timeline with significant events. It's basically exactly the same sort of instrumentation you're adding here. Benoit Girard will work with you so we can have a common set of macros and instrumentation points that both SPS and your timeline can use.

Comment 76

[Olli Pettay [:smaug][[e-mail]]]

To not repeat some mistakes of the other instrumentation code, please make sure to not slow down any hot code paths.

Comment 77

[Honza Bambas (:mayhemer)]

First, I'm impressed on miscommunication here.  I was announcing this work a long time ago and it actually slipped few releases already because of reviews pending for a very long time...  Why didn't we sync sooner?  Did I miss some regular platform meeting where STS had been announced?

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #75)
> The SPS profiler has some macros to annotate its performance timeline with
> significant events. It's basically exactly the same sort of instrumentation
> you're adding here. Benoit Girard will work with you so we can have a common
> set of macros and instrumentation points that both SPS and your timeline can
> use.

I don't agree with this.  Purpose of VET (visual event tracer - this bug) is to have more generally defined events, crossing boundaries of methods and threads.  Purpose is, mainly, to have 3 phase state of an event: waiting, executing, done.  The waiting phase is the key: I want to allow tracking of how long an event waits in an event queue of a thread, how long we wait for locks or how long we wait for a response from network.  STS profiler does something completely else, if I understand correctly.

I really don't think mixing VET and STS is a good idea at all.  Also the API seems very incompatible.  I am binding an instance (object pointer) with a resource name (usually URI or a host name).  Events for a host name or URI then can be easily filtered and tracked in the visualizer.  STS doesn't do anything like that, if I understand correctly.  The namespace arg could be used as the resource ID, but building the identifier can sometimes be time consuming and I don't see a way to use STS calls for VET as are now.

(In reply to Olli Pettay [:smaug] from comment #76)
> To not repeat some mistakes of the other instrumentation code, please make
> sure to not slow down any hot code paths.

I took a great care about this.  VET is not using locks at all.  Data are buffered per-thread (private thread data).  Only when the buffer is filled, data are 'sent' to a background low-priority I/O dedicated thread that writes them on disk.  There is of course a lock but used extremely rarely and always for a very short time (just copy two global vars) and cannot be blocked on I/O.

Comment 78

[Robert O'Callahan (:roc) (email my personal email if necessary)]

(In reply to Honza Bambas (:mayhemer) from comment #77)
> First, I'm impressed on miscommunication here.  I was announcing this work a
> long time ago and it actually slipped few releases already because of
> reviews pending for a very long time...  Why didn't we sync sooner?

I don't know.

> (In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #75)
> I really don't think mixing VET and STS is a good idea at all.  Also the API
> seems very incompatible.  I am binding an instance (object pointer) with a
> resource name (usually URI or a host name).  Events for a host name or URI
> then can be easily filtered and tracked in the visualizer.  STS doesn't do
> anything like that, if I understand correctly.  The namespace arg could be
> used as the resource ID, but building the identifier can sometimes be time
> consuming and I don't see a way to use STS calls for VET as are now.

The way you associate events with object instances is cool but there's still a lot of overlap here. Are you interested in latency created by main-thread activity such as restyling and reflow? Because SPS has instrumentation for that. On the flip side, I think all the information you're gathering would be useful to show in SPS.

SPS defines SAMPLE_MARKER to record instants and SAMPLE_LABEL and SAMPLE_LABEL_PRINTF to record intervals (limited to intervals corresponding to function invocations). You have MOZ_EVENT_TRACER_MARK to record instants (per object instance), MOZ_EVENT_TRACER_EXEC and MOZ_EVENT_TRACER_DONE to record intervals (per object instance), and MOZ_EVENT_TRACER_WAIT to record wait starts (per object instance). There's also a third instrumentation API, FunctionTimer.h, which has NS_TIME_FUNCTION to time function invocations and NS_TIME_FUNCTION_FMT to time function invocations associated with particular objects (a crude form of your object instances; see http://dxr.lanedo.com/search.cgi?tree=mozilla-central&string=NS_TIME_FUNCTION_FMT).

All three have different ways of recording and reading data and none of them can share data or code with any of the others. Both SPS and VET have their own thread-local buffers. We already have at least one function (PresShell::DoReflow) that's instrumented two different ways.

Why can't we have a single set of macros that capture data into a single set of buffers that can be used by both SPS and the visual event timeline?

Comment 79

[Honza Bambas (:mayhemer)]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #78)
> Why can't we have a single set of macros that capture data into a single set
> of buffers that can be used by both SPS and the visual event timeline?

Thank you for this reply.  It perfectly outlines the state.

I took your first comment as I have to turn to using or adopt the existing STS API.  That is not easily possible.

To have one and only APIs to use for everything is something that we obviosly need now, you are right on this point.

I think the design should be in a different (new) bug that will block this one.  Since there is currently no instrumentation for VET landed, we can change it simply w/o any wide code changes.

If you agree, we should discuss the API there.

Comment 80

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Sounds great, thanks! BTW the person you need to discuss this with is BenWa --- I'm just the matchmaker :-).

Comment 81

[Benoit Girard (:BenWa)]

(In reply to Honza Bambas (:mayhemer) from comment #79)
> Thank you for this reply.  It perfectly outlines the state.
> 
> I took your first comment as I have to turn to using or adopt the existing
> STS API.  That is not easily possible.
> 
> To have one and only APIs to use for everything is something that we
> obviosly need now, you are right on this point.
> 

Yes, as I understand it roc' point was to share a common instrumentation and API to prevent littering the code base with VET/SPS/FUNCTION_TIMER probes. We should be able to come up with a macro that receives all the information we're interested in and depending on your build configuration will pass it to the correct tool(s) being compiled.

SPS currently has the following interface: 'tools/profiler/sampler.h'. SAMPLE_LABEL and SAMPLE_MARKER are the primary instrumentation macro. We'll need to find a common interface. I'll take a look at VET first.

> I think the design should be in a different (new) bug that will block this
> one.  Since there is currently no instrumentation for VET landed, we can
> change it simply w/o any wide code changes.
> 
> If you agree, we should discuss the API there.

I agree that a new bug is appropriate.

Comment 82

[Michal Novotny [:michal]]

Comment on attachment 635378 [details] [diff] [review]
part4 v2.1 - some profiler instrumentation for cache

(In reply to Honza Bambas (:mayhemer) from comment #64)
> (In reply to Michal Novotny (:michal) from comment #63)
> > Comment on attachment 635130 [details] [diff] [review]
> > part4 v2 - some profiler instrumentation for cache
> 
> > Why don't you use the key from request here?
> 
> Because it is already freed (null) in the request.  There is no other way to
> access the key, at least AFAIK.

Bug 779461 changed this, so now you can use the key from the request. r+ with this change

Comment 83

[Honza Bambas (:mayhemer)]

(In reply to Michal Novotny (:michal) from comment #82)
> Bug 779461 changed this, so now you can use the key from the request. r+
> with this change

Thanks!

Comment 84

[Honza Bambas (:mayhemer)]

Attachment: Instrumentation in one patch

Already reviewed, just added a namespace to each event name to allow grouping.

This is intended to land.  Any API coalescing with the gecko profiler will be done, if possible, in a followup bug.

Comment 85

[Honza Bambas (:mayhemer)]

Attachment: visual event tracer service

- adds a service that turns tracing on and off, gets the log ; intended for use by a visualization extension
- record batch size decreased to reduce memory usage
- there is a lock that needs to be entered when a thread logs its first event into its batch ; this could be considered as something that could have influence on the normal program run ; no I/O made under the lock, only protects memory pointers

Comment 86

[Honza Bambas (:mayhemer)]

Appetizer, for real now, if you want to try this feature your self:


- install a build from this try run: https://tbpl.mozilla.org/?tree=Try&rev=57d0794b4bf1
- install http://www.janbambas.cz/moz/[e-mail] extension
- goto about:timeline
- press [ Start ] button
- load some web page (best in a new tab)
- return back to about:timeline tab
- press [ Stop ] button
- see the nice timeline of all events in the networking and cache layer

Comment 87

[Honza Bambas (:mayhemer)]

Comment on attachment 721545 [details] [diff] [review]
visual event tracer service

Switching to Ehsan that actually have reviewed this code in the past, thanks.  Sorry Benjamin for spam.

Comment 88

[(no longer active)]

Comment on attachment 721545 [details] [diff] [review]
visual event tracer service

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

Sorry for the lag.

Comment 89

[Honza Bambas (:mayhemer)]

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/260e98308023
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/85dd7094b78d


Ehsan, thanks for the review.

Comment 90

[Honza Bambas (:mayhemer)]

Bustage fix: https://hg.mozilla.org/integration/mozilla-inbound/rev/74ff7f32edd8

Comment 91

[Honza Bambas (:mayhemer)]

And bustage fix for event tracer enabled builds: https://hg.mozilla.org/integration/mozilla-inbound/rev/727777280043

Comment 92

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/260e98308023
https://hg.mozilla.org/mozilla-central/rev/85dd7094b78d
https://hg.mozilla.org/mozilla-central/rev/74ff7f32edd8
https://hg.mozilla.org/mozilla-central/rev/6da10679d191
https://hg.mozilla.org/mozilla-central/rev/727777280043