944706 - Tracelogger: Handle OOM somewhat cleaner.

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Hannes Verschore [:h4writer]]

Currently when a bigger tree is needed and we cannot alloc it, we will just disable tracelogger totally.

In version 0.1 this was done better, by outputting the already logged entries and reuse the max alloc we could. Now since we are logging a tree, instead of entries this is somewhat more complicated.

We need to output the tree, but not all entries are final yet. We sometimes still change the hasChildren/stop/nextId. So we need some code to patch this in the already printed output.

Comment 1

[Hannes Verschore [:h4writer]]

Attachment: tracelogging-flushing-and-patching

So this brings version 0.2 on parity with 0.1 with respect how much data it can handle. It makes it possible to already flush entries and afterwards patch, if something needs to get changed. This is a uncommon case, so no cache to wait until the end to patch.

Comment 2

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8396659 [details] [diff] [review]
tracelogging-flushing-and-patching

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

I think I found something. See comment for updateNextId ;)

::: js/src/TraceLogging.cpp
@@ +171,5 @@
> +        return;
> +
> +    if (treeFile) {
> +        // Format data in big endian.
> +        for (uint32_t i = 0; i < tree.size(); i++)

nit: size_t i = 0

@@ +174,5 @@
> +        // Format data in big endian.
> +        for (uint32_t i = 0; i < tree.size(); i++)
> +            entryToBigEndian(&tree[i]);
> +
> +        fseek(treeFile, 0, SEEK_END);

please check the return value

@@ +184,5 @@
> +            return;
> +        }
> +
> +        treeOffset += tree.currentId();
> +        tree.clear();

Maybe we should rename clear() to resetId() to make it clearer of what's going on here, what do you think?

@@ +367,5 @@
> +TraceLogger::getTreeEntry(uint32_t treeId, TreeEntry *entry)
> +{
> +    if (treeId < treeOffset) {
> +        fseek(treeFile, treeId * sizeof(TreeEntry), SEEK_SET);
> +        fread((void *)entry, sizeof(TreeEntry), 1, treeFile);

please check return values

@@ +371,5 @@
> +        fread((void *)entry, sizeof(TreeEntry), 1, treeFile);
> +
> +        entryToSystemEndian(entry);
> +    } else {
> +        *entry = tree[treeId];

ogod, that's a copy. You might want to change the API to fix that (make entry being a TreeEntry**? return a rval reference to a TreeEntry? your call)

@@ +378,5 @@
> +
> +void
> +TraceLogger::saveTreeEntry(uint32_t treeId, TreeEntry *entry)
> +{
> +    fseek(treeFile, treeId * sizeof(TreeEntry), SEEK_SET);

please check return value

@@ +402,5 @@
> +    tree[treeId - treeOffset].u.s.hasChildren = hasChildren;
> +}
> +
> +void
> +TraceLogger::updateNextId(uint32_t treeId, bool nextId)

!!!! nextId should be an uint32_t, not a bool!

@@ +437,5 @@
>          return;
>  
>      if (!tree.ensureSpaceBeforeAdd() || !stack.ensureSpaceBeforeAdd()) {
> +        uint64_t start = rdtsc() - traceLoggers.startupTime;
> +        flush();

You could make flush return a bool and then |if (!flush()) return;|

@@ +443,5 @@
> +        if (failed)
> +            return;
> +
> +        startEvent(TraceLogger::TL, start);
> +        stopEvent();

Not sure why these startEvent and stopEvent occur here?

@@ +448,2 @@
>      }
> +    

nit: trailing whitespace

@@ +497,5 @@
>  
>  void
>  TraceLogger::stopEvent(uint32_t id)
>  {
> +    //MOZ_ASSERT_IF(enabled, tree[stack.current().treeId].u.s.textId == id);

nit: commented assertion

@@ +508,5 @@
>      if (!enabled)
>          return;
>  
>      uint64_t stop = rdtsc() - traceLoggers.startupTime;
> +    //tree[stack.current().treeId].stop = stop;

nit: commented line

::: js/src/TraceLogging.h
@@ +284,5 @@
>      FILE *treeFile;
>      FILE *eventFile;
>  
>      bool enabled;
> +    bool failed;

Uses of failed let me think that it's always equal to !enabled and used in situations where !enabled is also tested. Could you remove it?

@@ +314,5 @@
> +    void startEvent(uint32_t id, uint64_t timestamp);
> +
> +    // Update functions that can adjust the items in the tree,
> +    // both in memory or already written to disk.
> +    void updateHasChildren(uint32_t treeId, bool hasChildren = true);

nit: default value for hasChildren has turned from false to true?

Comment 3

[Hannes Verschore [:h4writer]]

Comment on attachment 8396659 [details] [diff] [review]
tracelogging-flushing-and-patching

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

::: js/src/TraceLogging.cpp
@@ +435,5 @@
>  {
>      if (!enabled)
>          return;
>  
>      if (!tree.ensureSpaceBeforeAdd() || !stack.ensureSpaceBeforeAdd()) {

This code only reduces the "tree" size. It doesn't contain any code to recover when the stack can't get increased. So this code should be under if (!tree.ensureSpaceBeforeAdd()) and still fail (=stop logging) when stack.ensureSpaceBeforeAdd() fails.

Comment 4

[Hannes Verschore [:h4writer]]

Attachment: tracelogging_fixed

(In reply to Benjamin Bouvier [:bbouvier] from comment #2)
> @@ +184,5 @@
> > +            return;
> > +        }
> > +
> > +        treeOffset += tree.currentId();
> > +        tree.clear();
> 
> Maybe we should rename clear() to resetId() to make it clearer of what's
> going on here, what do you think?

I think this is consistent with Vector.clear(), which doesn't remove the internal space, but only set length to 0. It is only the Vector.clearAndFree() which removes all items and frees the alloc'ed data.
 
> @@ +371,5 @@
> > +        fread((void *)entry, sizeof(TreeEntry), 1, treeFile);
> > +
> > +        entryToSystemEndian(entry);
> > +    } else {
> > +        *entry = tree[treeId];
> 
> ogod, that's a copy. You might want to change the API to fix that (make
> entry being a TreeEntry**? return a rval reference to a TreeEntry? your call)

Yes it will copy, since we need allocate the space outside this function to get the fread working. I don't want to malloc/free here. As a consequence the in memory case just copies the data. This is only used by the DEBUG asserts. In the other cases (update*) we don't ask the getTreeEntry but do it immediately in memory. That's why I didn't "fixed" this.


> @@ +402,5 @@
> > +    tree[treeId - treeOffset].u.s.hasChildren = hasChildren;
> > +}
> > +
> > +void
> > +TraceLogger::updateNextId(uint32_t treeId, bool nextId)
> 
> !!!! nextId should be an uint32_t, not a bool!

Good find!

> @@ +443,5 @@
> > +        if (failed)
> > +            return;
> > +
> > +        startEvent(TraceLogger::TL, start);
> > +        stopEvent();
> 
> Not sure why these startEvent and stopEvent occur here?

Added a comment. This attributes the time it took to flush() to Tracelogger. Just to make sure nobody thinks a particular function was slow, if we just happen to flush there.

> 
> ::: js/src/TraceLogging.h
> @@ +284,5 @@
> >      FILE *treeFile;
> >      FILE *eventFile;
> >  
> >      bool enabled;
> > +    bool failed;
> 
> Uses of failed let me think that it's always equal to !enabled and used in
> situations where !enabled is also tested. Could you remove it?
Failed != !enabled.
Failed means it cannot proceed anymore. Enabled means it will currently not log a thing, but can get enabled again if !failed. The distinction isn't used atm, but will in future patches.

> @@ +314,5 @@
> > +    void startEvent(uint32_t id, uint64_t timestamp);
> > +
> > +    // Update functions that can adjust the items in the tree,
> > +    // both in memory or already written to disk.
> > +    void updateHasChildren(uint32_t treeId, bool hasChildren = true);
> 
> nit: default value for hasChildren has turned from false to true?

The default should always has been "true". My mistake in the first patch.

There are also a few other nits in this patch. As saving the mainthread loggers so we can probably delete them (i.e. causing them to log their data).

Comment 5

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8400750 [details] [diff] [review]
tracelogging_fixed

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

Looks good!

::: js/src/TraceLogging.cpp
@@ +597,5 @@
>      }
>  
> +    for (size_t i = 0; i < mainThreadLoggers.length(); i++) {
> +        delete mainThreadLoggers[i];
> +    }

nit: no need for parenthesis, unless you add mainThreadLoggers[i] = nullptr; (up to you)

::: js/src/TraceLogging.h
@@ +310,5 @@
> +    bool getTreeEntry(uint32_t treeId, TreeEntry *entry);
> +    bool saveTreeEntry(uint32_t treeId, TreeEntry *entry);
> +
> +    // This contains the meat of startEvent, except if there is enough space,
> +    // the check if tracelogger is enabled and the timestamp computation.

nit: maybe a missing "not" before "enough space"? or the phrasing looks weird.

Comment 6

[Hannes Verschore [:h4writer]]

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

Comment 7

[Ed Morley [:emorley]]

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