Closed Bug 1444976 Opened 6 years ago Closed 6 years ago

Define, implement and land a way to measure audio thread load during a scenario

Categories

(Core :: WebRTC: Audio/Video, enhancement, P2)

Product:
Core
Component:
WebRTC: Audio/Video
Type:
enhancement

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla61
Tracking Flags:
Tracking Status
firefox61 --- fixed

People

(Reporter: padenot, Assigned: padenot)

References

(Blocks 1 open bug)

Details

Attachments

(4 files, 2 obsolete files)

Bug 1444976 - Implement a lock-free asynchronous logging system to be used from real-time audio and video code.
59 bytes, text/x-review-board-request
froydnj
: review+
Details
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media.
59 bytes, text/x-review-board-request
pehrsons
: review+
Details
Bug 1444976 - Trace some initial real-time media stuff.
59 bytes, text/x-review-board-request
pehrsons
: review+
Details
Screenshot of the other tool
70.28 KB, image/png
Details 
A lot of our quality issues comes from the fact that sometimes the audio thread, which defines the main clock of the whole media subsystem, is too busy, and underruns.

Not only does this cause audio glitches, but it makes the main clock go off and then, because most things are driven from this main clock (as they should), any number of bad situations can happen. We cannot have a robust system with the main clock going off at random times.

Fixing the performance issues themselves is covered by bug 1405440 and all its descendant (and possibly others, not filed at the minute), but it's crucial to be able to make those changes with confidence.

In this bug, I'll implement some stuff (C++ code, testing code, reporting code, etc.) to be able to easily know whether or not an optimization is worth it in a given scenario (peers, hardware, software, external load, etc.).

After having this objective metric (maybe metrics) landed and integrated, it will be easier to be able to say with confidence that we're going in the right direction, and we'll tackle other performance issues, not necessarily audio related.

Hopefully it will also be possible to have people run this in the field on configurations we don't have, for reporting.

I'm also investigating custom ETW/Chrome tracing code to go alongside (or replace) this "load index".
Rank: 10
This also has an integration testing/automatic reporting part, but we'll handle it separately, there is too much unknown about what to use currently.
That's exciting, let me know if I can support you on that.
https://paul.cx/public/tracing.mp4 is a screencast of this. Of course we need to add bunch of probes.
This is a screenshot of another tool I've made, that is going to be useful to do regression analysis, and a first high level diagnosing:
- x is time (same time as the other tool)
- y is the load of the callback for a single callback, defined as the ratio of the actual rendering time in seconds over the theoretical callback budget in seconds. The theoretical budget in seconds is the number of frames the thread has to render for this callback, divided by the sampling rate at which the data are rendered

We trivially see under-runs, it's when there is a blue spike, over 1.0, and then we can dig in with the other tool.

We also see that our standard deviation is very very wide (= very bad).

This screenshot is of a session recorded on Linux.
Nils, have a look at this. I'm now looking into landing and making it togglable at runtime.
Flags: needinfo?(drno)
Cool. Thanks

Can the result only be loaded in Chrome as in the video, or was that only for prototyping?

Would it be possible to not write this into Moz logs, but instead collect and download from memory? But only pursue that if it's low effort.
Flags: needinfo?(drno)
(In reply to Nils Ohlmeier [:drno] from comment #11)
> Cool. Thanks
> 
> Can the result only be loaded in Chrome as in the video, or was that only
> for prototyping?
> 
> Would it be possible to not write this into Moz logs, but instead collect
> and download from memory? But only pursue that if it's low effort.

Those traces are loadable in the trace-viewer component of Catapult, which is what chrome://tracing is based on. The file format is just JSON though, I'm also using the same format for other things.

Nothing is high effort here. What is important is ergonomics.
Blocks: 1447945
Attachment #8960683 - Attachment is obsolete: true
Attachment #8960684 - Attachment is obsolete: true
Comment on attachment 8960681 [details]
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media.

https://reviewboard.mozilla.org/r/229436/#review236530

::: dom/media/Tracing.h:1
(Diff revision 2)
> +/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
> +/* This Source Code Form is subject to the terms of the Mozilla Public
> + * License, v. 2.0. If a copy of the MPL was not distributed with this file,
> + * You can obtain one at http://mozilla.org/MPL/2.0/. */

Missing a vim line per https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Coding_Style#Mode_Line

::: dom/media/Tracing.h:23
(Diff revision 2)
> +#define TRACING
> +
> +#ifdef TRACING
> +  /* TRACE is for use in the real-time audio rendering thread.
> +   * It would be better to always pass in the thread id. However, the thread an
> +   * audio callback can change when the underlying audio device change, and also

"the thread an audio callback runs on can change..."?
                              ^^^^^^^^

::: dom/media/Tracing.h:26
(Diff revision 2)
> +  /* TRACE is for use in the real-time audio rendering thread.
> +   * It would be better to always pass in the thread id. However, the thread an
> +   * audio callback can change when the underlying audio device change, and also
> +   * it seems to be called from a thread pool in a round-robin fashion when
> +   * audio remoting is activated, making the traces unreadable.
> +   * The thread on which the AudioCallbackDriver::DataCallback is set to always

"DataCallback runs is set to..."?
              ^^^^^

::: dom/media/Tracing.h:27
(Diff revision 2)
> +   * be thread 0, and the budget is set to always be thread 1. This allows those
> +   * displaying the elements in two separate lanes.

s/those displaying the/displaying those/ ?

::: dom/media/Tracing.h:54
(Diff revision 2)
> +
> +
> +class MOZ_RAII AutoTracer
> +{
> +public:
> +  enum EventType

enum class for stronger type safety

::: dom/media/Tracing.h:77
(Diff revision 2)
> +             uint64_t aFrames);
> +  ~AutoTracer();
> +private:
> +  uint64_t NowInUs();
> +
> +  enum TracingPhase

enum class

::: dom/media/Tracing.h:106
(Diff revision 2)
> +  AsyncLogger& mLogger;
> +  const char* mLocation;
> +  const char* mComment;
> +  EventType mEventType;
> +  uint64_t mPID;
> +  uint64_t mTID;

Can you comment these? They look mostly self explanatory but lifetime for mLogger looks like a footgun so that could use a few more words.

Can the primitives be const?

::: dom/media/Tracing.cpp:1
(Diff revision 2)
> +/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
> +/* This Source Code Form is subject to the terms of the Mozilla Public
> + * License, v. 2.0. If a copy of the MPL was not distributed with this file,
> + * You can obtain one at http://mozilla.org/MPL/2.0/. */

Same missing line here

::: dom/media/Tracing.cpp:6
(Diff revision 2)
> +#include <cstdint>
> +#include <inttypes.h>
> +#include <cstdio>
> +#include "mozilla/TimeStamp.h"
> +#include "AsyncLogger.h"
> +#include "Tracing.h"

Coding style says:

> Includes are split into three blocks, and sorted alphabetically in each block:
> 
> 1 The main header: #include "Foo.h" in Foo.cpp
> 2 Standard library includes: #include <map>
> 3 Mozilla includes: #include "mozilla/dom/Element.h"

::: dom/media/Tracing.cpp:6
(Diff revision 2)
> +/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
> +/* This Source Code Form is subject to the terms of the Mozilla Public
> + * License, v. 2.0. If a copy of the MPL was not distributed with this file,
> + * You can obtain one at http://mozilla.org/MPL/2.0/. */
> +
> +#include <cstdint>

<cstdint> is included in the header too. Where is it needed?

::: dom/media/Tracing.cpp:33
(Diff revision 2)
> +           "{\"name\": \"%s\", \"cat\": \"%s\", \"ph\": \"%c\","
> +           "\"ts\": %" PRIu64 ", \"pid\": %" PRIu64 ", \"tid\": %" PRIu64 ", \"args\": { \"comment\": \"%s\"}},",

You might want to consider a raw string literal instead of all the escaping.

::: dom/media/Tracing.cpp:51
(Diff revision 2)
> +           "{\"name\": \"%s\", \"cat\": \"%s\", \"ph\": \"X\","
> +           "\"ts\": %" PRIu64 ", \"dur\": %" PRIu64 ", \"pid\": %" PRIu64 ","
> +           "\"tid\": %" PRIu64 ", \"args\": { \"comment\": %" PRIu64 "}},",

You might want to consider a raw string literal instead of all the escaping.

::: dom/media/Tracing.cpp:102
(Diff revision 2)
> +  if (!mLogger.Enabled()) {
> +    return;
> +  }

Can `mLogger.Enabled()` change between ctor and dtor? Then consider storing your own state in a member instead.
Attachment #8960681 - Flags: review?(apehrson) → review+
Comment on attachment 8960681 [details]
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media.

https://reviewboard.mozilla.org/r/229436/#review236536

::: dom/media/Tracing.h:31
(Diff revision 2)
> +  #define TRACE(aLogger)                                                       \
> +    AutoTracer trace(aLogger, __PRETTY_FUNCTION__, getpid(), 0);

The name of this trace should IMO be explicit about being the audio callback thread.

::: dom/media/Tracing.h:33
(Diff revision 2)
> +  #define TRACE_BUDGET(aLogger, aFrames, aSampleRate) \
> +    AutoTracer budget(aLogger, "Real-time budget", getpid(), 1,                \
> +                      AutoTracer::EventType::BUDGET, aFrames, aSampleRate);

And this should be explicit about being the audio callback's budget.

::: dom/media/Tracing.h:36
(Diff revision 2)
> +  #define TRACE_ON_THREAD(aLogger)                                             \
> +    AutoTracer trace(aLogger, __PRETTY_FUNCTION__, getpid(),                   \
> +                     std::hash<std::thread::id>{}(std::this_thread::get_id()));

Then this seems more like the default trace method, can it be named `TRACE`?
Comment on attachment 8960682 [details]
Bug 1444976 - Trace some initial real-time media stuff.

https://reviewboard.mozilla.org/r/229438/#review236534

Overall this is brilliant and exactly what we need, thanks!

::: dom/media/GraphDriver.cpp:8
(Diff revision 2)
>   * License, v. 2.0. If a copy of the MPL was not distributed with this file,
>   * You can obtain one at http://mozilla.org/MPL/2.0/. */
>  
>  #include <MediaStreamGraphImpl.h>
>  #include "mozilla/dom/AudioContext.h"
> +#include "Tracing.h"

The sorting here is.. interesting.

::: dom/media/MediaStreamGraph.cpp:3663
(Diff revision 2)
>      if (NS_FAILED(rv)) {
>        NS_WARNING("Could not create dispatch bounce thread for the MSG, falling back to direct dispatch");
>        mDispatchBounceThread = nullptr;
>      }
> +
> +    mTraceLogger.Start();

This sounds like it will always start the logger. Can we make it clear that it's a noop if logging is not enabled for the MSGTracing module?

::: dom/media/MediaStreamGraph.cpp:3671
(Diff revision 2)
> +
> +

Unnecessary

::: dom/media/MediaStreamGraphImpl.h:830
(Diff revision 2)
>    AudioMixer mMixer;
>    const RefPtr<AbstractThread> mAbstractMainThread;
>    RefPtr<SharedThreadPool> mThreadPool;
>    RefPtr<nsIThread> mDispatchBounceThread;
> +  AsyncLogger mTraceLogger;
> +  std::atomic<bool> mIsTracing;

This doesn't seem used.

::: media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp:54
(Diff revision 2)
>  #include "transportflow.h"
>  #include "transportlayer.h"
>  #include "transportlayerdtls.h"
>  #include "transportlayerice.h"
>  
> +#include "Tracing.h"

Stick it with the moz includes above. (so remove a newline)
Attachment #8960682 - Flags: review?(apehrson) → review+
Attachment #8960680 - Flags: review?(nfroyd)
Comment on attachment 8960680 [details]
Bug 1444976 - Implement a lock-free asynchronous logging system to be used from real-time audio and video code.

https://reviewboard.mozilla.org/r/229434/#review237222

I haven't reviewed the atomicity bits in detail (wow, there are a lot of relaxed loads running around), but I have enough comments that maybe we can work in parallel somewhat.

::: dom/media/AsyncLogger.h:5
(Diff revision 2)
> +#ifndef ASYNC_LOGGER
> +#define ASYNC_LOGGER

The include guard here should be mozilla_dom_AsyncLogger_h or somesuch.  This patch also doesn't add the moz.build bits.

A one-line summary prior to the include guard makes the file look nice in Searchfox/DXR directory listings and is helpful for the reader regardless.

::: dom/media/AsyncLogger.h:13
(Diff revision 2)
> +template<size_t MESSAGE_LENGTH>
> +class MPSCQueue

All of this code should be in the `mozilla` namespace, yes?

I can't believe it's 2018 and we're writing lock-free code with zero documentation?  That doesn't seem right.

::: dom/media/AsyncLogger.h:22
(Diff revision 2)
> +    MPSCQueue()
> +    : mHead(new Message())
> +    , mTail(mHead.load(std::memory_order_relaxed))
> +    {
> +        Message* front = mHead.load(std::memory_order_relaxed);
> +        front->mNext.store(nullptr, std::memory_order_relaxed);

Maybe it would be better to just initialize mNext in the Message constructor itself?  Would save code in `Push`, too.

::: dom/media/AsyncLogger.h:85
(Diff revision 2)
> +  // The goal here is to make it easy on the allocator. We pack a pointer in the
> +  // message struct, and we still want to do power of two allocations to

Maybe `Message` should expose some static const member for determining how much non-character string data it has, and we could avoid hard-coding assumptions about `Message` into the comments and other code?

::: dom/media/AsyncLogger.h:125
(Diff revision 2)
> +    } else {
> +      MOZ_ASSERT(!mRunning && !mThread);
> +    }
> +  }
> +
> +  void Log(const char aMessage[MAX_MESSAGE_LENGTH]) {

This is going to be a really inconvenient API, isn't it?  Or do you really want people to write code like:

```
  char buf[mAsyncLogger.MAX_MESSAGE_LENGTH];
  SprintfLiteral(buf, "...", ...);
  mAsyncLogger.Log(buf);
```

?

::: dom/media/AsyncLogger.h:138
(Diff revision 2)
> +    return MOZ_LOG_TEST(mLogModule, mozilla::LogLevel::Verbose);
> +  }
> +private:
> +  void Run()
> +  {
> +    MOZ_ASSERT(!Enabled());

I don't get this assert.  Above, in `Start()`, you only call `Run()` if `Enabled()`, but here, you assert the opposite condition?

::: dom/media/AsyncLogger.h:140
(Diff revision 2)
> +      while (mRunning) {
> +        char message[MAX_MESSAGE_LENGTH];
> +        while (mMessageQueue.Pop(message)) {
> +          MOZ_LOG(mLogModule, mozilla::LogLevel::Verbose, ("%s", message));
> +        }
> +        Sleep();

This is going to chew CPU. :(  I guess that's only happening when logging is enabled, yes?  So maybe it's not that bad.

::: dom/media/AsyncLogger.h:142
(Diff revision 2)
> +        while (mMessageQueue.Pop(message)) {
> +          MOZ_LOG(mLogModule, mozilla::LogLevel::Verbose, ("%s", message));
> +        }

What ensures that the thread calling `Stop()` and joining this logging thread doesn't get livelocked by other threads continually posting messages to the queue?
Attachment #8960680 - Flags: review?(nfroyd)
Comment on attachment 8960680 [details]
Bug 1444976 - Implement a lock-free asynchronous logging system to be used from real-time audio and video code.

https://reviewboard.mozilla.org/r/229434/#review237222

> The include guard here should be mozilla_dom_AsyncLogger_h or somesuch.  This patch also doesn't add the moz.build bits.
> 
> A one-line summary prior to the include guard makes the file look nice in Searchfox/DXR directory listings and is helpful for the reader regardless.

Nice, didn't know about the single line summary thing.

> All of this code should be in the `mozilla` namespace, yes?
> 
> I can't believe it's 2018 and we're writing lock-free code with zero documentation?  That doesn't seem right.

I added quite a lot of docs in the next version, hopefully enough, but let me know.

> Maybe `Message` should expose some static const member for determining how much non-character string data it has, and we could avoid hard-coding assumptions about `Message` into the comments and other code?

I tried something, but it's not super elegant (I'm instantiating MPSCQueue with a dummy template value, that's hopefully culled because not used later), I'm open to suggestion on this one.

> This is going to be a really inconvenient API, isn't it?  Or do you really want people to write code like:
> 
> ```
>   char buf[mAsyncLogger.MAX_MESSAGE_LENGTH];
>   SprintfLiteral(buf, "...", ...);
>   mAsyncLogger.Log(buf);
> ```
> 
> ?

Yes, that's the point. Something on top can choose to output formatted or unformatted strings. This class is merely about the async logging part.

> I don't get this assert.  Above, in `Start()`, you only call `Run()` if `Enabled()`, but here, you assert the opposite condition?

It's just a typo, I was building in opt and didn't notice it, fixed.

> This is going to chew CPU. :(  I guess that's only happening when logging is enabled, yes?  So maybe it's not that bad.

If we're running this, then we're also running one or more real-time threads that are heavily loaded, and wake-up every 3 to 10ms to do some work heavy DSP work, plus multiple video encoders and decoders.

I made sure it's doing nothing when the log is disabled indeed. This is going to be critical to be able to diagnose in the field.

> What ensures that the thread calling `Stop()` and joining this logging thread doesn't get livelocked by other threads continually posting messages to the queue?

Nothing, you're right. I've added another check for `mRunning` in the inner loop.
Comment on attachment 8960680 [details]
Bug 1444976 - Implement a lock-free asynchronous logging system to be used from real-time audio and video code.

https://reviewboard.mozilla.org/r/229434/#review238528

The comments are great, thank you.  Nits and suggestions below.

::: dom/media/AsyncLogger.h:12
(Diff revision 3)
> +#ifndef mozilla_dom_AsyncLogger_h
> +#define mozilla_dom_AsyncLogger_h
> +
> +#include <atomic>
> +#include <thread>
> +#include <mozilla/Logging.h>

Nit: we typically include mozilla headers with quotes, so `#include "mozilla/Logging.h"`.

::: dom/media/AsyncLogger.h:30
(Diff revision 3)
> +template<size_t MESSAGE_LENGTH>
> +class MPSCQueue

Should this go in `mozilla::detail`, because we don't expect people to use the queue outside of the `AsyncLogger` facility?

::: dom/media/AsyncLogger.h:92
(Diff revision 3)
> +        Message* prev = mHead.exchange(msg, std::memory_order_acq_rel);
> +        prev->mNext.store(msg, std::memory_order_release);
> +    }
> +
> +    // Copy the content of the first message of the queue to aOutput, and
> +    // frees its associated memory. Returns true if there was a message, in

Maybe "frees the message", so it's clear that "its" doesn't refer to `aOutput`, which would be confusing!

::: dom/media/AsyncLogger.h:109
(Diff revision 3)
> +        // null, then only the sentinel node was present in the queue, we can
> +        // safely return false.
> +        // mTail can be loaded with relaxed ordering, since it's not written nor
> +        // read by any other thread (this queue is single consumer).
> +        // mNext can be written to by one of the producer, so it's necessary to
> +        // ensure those write are seen, hence the stricter ordering.

Nit: "those writes"?

::: dom/media/AsyncLogger.h:127
(Diff revision 3)
> +        // It's only necessary to ensure the previous load on this thread is not
> +        // reordered past this line, so release ordering is sufficient here.
> +        mTail.store(next, std::memory_order_release);
> +
> +        // This thread is now the only thing that points to `tail`, it can be
> +        // safelu deleted.

Nit: "safely".

::: dom/media/AsyncLogger.h:164
(Diff revision 3)
> +    // making it cheap and, more importantly, lock-free enough.
> +    static const size_t MESSAGE_PADDING = sizeof(Message::mNext);
> +private:
> +    enum {
> +        alloc_size = MESSAGE_LENGTH + MESSAGE_PADDING,
> +        alloc_size_pot = alloc_size && !(alloc_size & (alloc_size - 1))

We have `IsPowerOfTwo` in mozilla/MathAlgorithms.h for this.  It's even `constexpr`, so you can use it in `static_assert`s.  Please use that function instead of this enum.  Probably can dispense with this `enum` entirely after that?

::: dom/media/AsyncLogger.h:219
(Diff revision 3)
> +  void Log(const char aMessage[MAX_MESSAGE_LENGTH]) {
> +    if (Enabled()) {
> +      mMessageQueue.Push(aMessage);

On the subject of more convenient APIs, I wonder if it'd be nicer if `Log()` was more like:

```
// Maybe a variadic template function, so we don't have to use `va_list`?
void Log(const char* format, ...) MOZ_FORMAT_PRINTF {
  if Enabled() {
    auto* msg = new Message();
    va_list args;
    va_start(args, format);
    VsprintfLiteral(msg->data, format, args);
    va_end(args);
    // pass to some Message method to insert into queue
  }
}
```

Which would save you some memory copies, save some stack space, and save people writing out `char buf[BLAH]` everywhere.
Attachment #8960680 - Flags: review?(nfroyd) → review+
(In reply to Nathan Froyd [:froydnj] from comment #24)
> ::: dom/media/AsyncLogger.h:219
> (Diff revision 3)
> > +  void Log(const char aMessage[MAX_MESSAGE_LENGTH]) {
> > +    if (Enabled()) {
> > +      mMessageQueue.Push(aMessage);
> 
> On the subject of more convenient APIs, I wonder if it'd be nicer if `Log()`
> was more like:
> 
> ```
> // Maybe a variadic template function, so we don't have to use `va_list`?
> void Log(const char* format, ...) MOZ_FORMAT_PRINTF {
>   if Enabled() {
>     auto* msg = new Message();
>     va_list args;
>     va_start(args, format);
>     VsprintfLiteral(msg->data, format, args);
>     va_end(args);
>     // pass to some Message method to insert into queue
>   }
> }
> ```
> 
> Which would save you some memory copies, save some stack space, and save
> people writing out `char buf[BLAH]` everywhere.

I've ended up doing something along those lines and it's indeed nicer, thanks.
Comment on attachment 8960681 [details]
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media.

https://reviewboard.mozilla.org/r/229436/#review237974

::: dom/media/Tracing.cpp:33
(Diff revision 2)
> +           "{\"name\": \"%s\", \"cat\": \"%s\", \"ph\": \"%c\","
> +           "\"ts\": %" PRIu64 ", \"pid\": %" PRIu64 ", \"tid\": %" PRIu64 ", \"args\": { \"comment\": \"%s\"}},",

I wish, but no, I need the inttypes.h format specifier, and they don't mix well.
We're sorry, Autoland could not rebase your commits for you automatically. Please manually rebase your commits and try again.

hg error in cmd: hg rebase -s 499cb3898def7b48044990388078d5efb631c3f3 -d 8a2ba99f199a: rebasing 455874:499cb3898def "Bug 1444976 - Implement a lock-free asynchronous logging system to be used from real-time audio and video code. r=froydnj"
rebasing 455875:b02d84fcc57c "Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media. r=pehrsons"
rebasing 455876:85a4af0aa942 "Bug 1444976 - Trace some initial real-time media stuff. r=pehrsons" (tip)
merging dom/media/MediaStreamGraph.cpp
merging dom/media/MediaStreamGraphImpl.h
warning: conflicts while merging dom/media/MediaStreamGraph.cpp! (edit, then use 'hg resolve --mark')
warning: conflicts while merging dom/media/MediaStreamGraphImpl.h! (edit, then use 'hg resolve --mark')
unresolved conflicts (see hg resolve, then hg rebase --continue)
Pushed by paul@paul.cx:
https://hg.mozilla.org/integration/mozilla-inbound/rev/75b4992b4a23
Implement a lock-free asynchronous logging system to be used from real-time audio and video code. r=froydjn
https://hg.mozilla.org/integration/mozilla-inbound/rev/390ce943cda8
Use the AsyncLog to implement a tracing subsystem for real-time media. r=pehrsons
https://hg.mozilla.org/integration/mozilla-inbound/rev/5a183343f307
Trace some initial real-time media stuff. r=pehrsons
Backed out 3 changesets (bug 1444976) for B, S and BR failures in z:\build\build\src\dom\media\AsyncLogger.h(47) on a CLOSED TREE

Failure: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified&selectedJob=171863025.
Problematic push: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=5a183343f3076337083fee652bc79614e80b2a40&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified
Backout: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=73ac46f2c72b27d192c4f974f0177fc83bf5c673&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified
Log: https://treeherder.mozilla.org/logviewer.html#?job_id=171863025&repo=mozilla-inbound&lineNumber=13906

15:28:53     INFO -  z:\build\build\src\dom\media\AsyncLogger.h(48): error C2229: struct 'mozilla::detail::MPSCQueue<0>::Message' has an illegal zero-sized array
15:28:53     INFO -  z:/build/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp(1935): error C2065: '__PRETTY_FUNCTION__': undeclared identifier
15:28:53     INFO -  z:/build/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp(1941): error C2065: '__PRETTY_FUNCTION__': undeclared identifier
15:28:53     INFO -  z:/build/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp(1953): error C2065: '__PRETTY_FUNCTION__': undeclared identifier
15:28:53     INFO -  z:/build/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp(2242): error C2065: '__PRETTY_FUNCTION__': undeclared identifier
15:28:53     INFO -  z:/build/build/src/config/rules.mk:1024: recipe for target 'Unified_cpp_src_mediapipeline0.obj' failed
15:28:53     INFO -  mozmake.EXE[5]: *** [Unified_cpp_src_mediapipeline0.obj] Error 2
15:28:53     INFO -  mozmake.EXE[5]: Leaving directory 'z:/build/build/src/obj-firefox/media/webrtc/signaling/src/mediapipeline'
15:28:53     INFO -  mozmake.EXE[5]: Entering directory 'z:/build/build/src/obj-firefox/media/webrtc/trunk/webrtc/modules/audio_coding/audio_decoder_interface_gn'
15:28:53     INFO -  z:/build/build/src/sccache2/sccache.exe z:/build/build/src/vs2017_15.6.0/VC/bin/Hostx64/x86/cl.exe -FoUnified_cpp_decoder_interface_gn0.obj -c -DNDEBUG -DTRIMMED=1 -DCHROMIUM_BUILD -DEXPAT_RELATIVE_PATH -DV8_DEPRECATION_WARNINGS -DWEBRTC_INCLUDE_INTERNAL_AUDIO_DEVICE -DWEBRTC_MOZILLA_BUILD -DWEBRTC_RESTRICT_LOGGING -DDYNAMIC_ANNOTATIONS_ENABLED=0 -DNVALGRIND -DCERT_CHAIN_PARA_HAS_EXTRA_FIELDS -DNOMINMAX -DNO_TCMALLOC -DNTDDI_VERSION=0x0A000000 -DPSAPI_VERSION=1 -DUNICODE -DWEBRTC_WIN -DWIN32 -DWIN32_LEAN_AND_MEAN -DWINVER=0x0A00 -D_ATL_NO_OPENGL -D_CRT_RAND_S -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SECURE_ATL -D_UNICODE -D_USING_V110_SDK71_ -D_WIN32_WINNT=0x0A00 -D_WINDOWS -D__STD_C -DSTATIC_EXPORTABLE_JS_API -DMOZ_HAS_MOZGLUE -DMOZILLA_INTERNAL_API -DIMPL_LIBXUL -Iz:/build/build/src/media/webrtc/trunk/webrtc/modules/audio_coding/audio_decoder_interface_gn -Iz:/build/build/src/obj-firefox/media/webrtc/trunk/webrtc/modules/audio_coding/audio_decoder_interface_gn -Iz:/build/build/src/obj-firefox/ipc/ipdl/_ipdlheaders -Iz:/build/build/src/ipc/chromium/src -Iz:/build/build/src/ipc/glue -Iz:/build/build/src/media/webrtc/trunk -Iz:/build/build/src/obj-firefox/dist/include -MD -FI z:/build/build/src/obj-firefox/mozilla-config.h -DMOZILLA_CLIENT -utf-8 -TP -nologo -w15038 -wd5026 -wd5027 -Zc:sizedDealloc- -wd4091 -wd4577 -D_HAS_EXCEPTIONS=0 -W3 -Gy -Zc:inline -arch:SSE2 -Gw -wd4251 -wd4244 -wd4267 -wd4800 -wd4595 -we4553 -D_SILENCE_TR1_NAMESPACE_DEPRECATION_WARNING -GR- -Z7 -O1 -Oi -Oy- -GL -deps.deps/Unified_cpp_decoder_interface_gn0.obj.pp    z:/build/build/src/obj-firefox/media/webrtc/trunk/webrtc/modules/audio_coding/audio_decoder_interface_gn/Unified_cpp_decoder_interface_gn0.cpp
15:28:53     INFO -  Unified_cpp_decoder_interface_gn0.cpp
15:28:53     INFO -  z:/build/build/src/obj-firefox/mozilla-config.h(124): warning C4005: 'WINVER': macro redefinition
15:28:53     INFO -  z:/build/build/src/obj-firefox/mozilla-config.h(124): note: command-line arguments:  see previous definition of 'WINVER'
15:28:53     INFO -  z:/build/build/src/obj-firefox/mozilla-config.h(132): warning C4005: '_WIN32_WINNT': macro redefinition
15:28:53     INFO -  z:/build/build/src/obj-firefox/mozilla-config.h(132): note: command-line arguments:  see previous definition of '_WIN32_WINNT'
15:28:53     INFO -  mozmake.EXE[5]: Leaving directory 'z:/build/build/src/obj-firefox/media/webrtc/trunk/webrtc/modules/audio_coding/audio_decoder_interface_gn'
15:28:53     INFO -  z:/build/build/src/config/recurse.mk:73: recipe for target 'media/webrtc/signaling/src/mediapipeline/target' failed
15:28:53     INFO -  mozmake.EXE[4]: *** [media/webrtc/signaling/src/mediapipeline/target] Error 2
15:28:53     INFO -  mozmake.EXE[4]: *** Waiting for unfinished jobs....
Flags: needinfo?(padenot)
Comment on attachment 8960681 [details]
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media.

Some changes:
- it now works on windows
- it's now global, so we can trace stuff deep down in webrtc.org land
Flags: needinfo?(padenot)
Attachment #8960681 - Flags: review+ → review?(apehrson)
Comment on attachment 8960681 [details]
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media.

https://reviewboard.mozilla.org/r/229436/#review242224

::: dom/media/Tracing.h:123
(Diff revisions 2 - 7)
>                     uint64_t aDuration,
>                     uint64_t aPID,
>                     uint64_t aThread,
>                     uint64_t aFrames);
>  
> -  AsyncLogger& mLogger;
> +  // The logger to use. It has a lifetime longer than the block an instance of

"It has" or "It must have"?

::: dom/media/Tracing.h:129
(Diff revisions 2 - 7)
> +  // this class traces.
> +  mozilla::AsyncLogger& mLogger;
> +  // The location for this trace point, arbitrary string litteral, often the
> +  // name of the calling function, with a static lifetime.
>    const char* mLocation;
> +  // A comment for this trace point, abitrary string litteral with a static

s/litteral/literal/

::: dom/media/Tracing.h:134
(Diff revisions 2 - 7)
> -  uint64_t mTID;
> +  // The process ID of the calling process, will be displayed in a separate
> +  // section in the trace visualizer.

maybe "Traces are separated by process ID in the trace visualizer" ? "grouped"?

::: dom/media/Tracing.h:137
(Diff revisions 2 - 7)
> +  // The thread ID of the calling thread, will be displayed in a separate
> +  // section in the trace visualizer.

Same here as for PID.

::: dom/media/Tracing.h:140
(Diff revisions 2 - 7)
> +  // Whether or not the logger is enabled, controling the output.
> +  const bool mLoggerEnabled;

Who controls enabling the logger? I.e., is this for us to keep track of the state we have put it in, or to be aware of its current state, set by someone else?

::: dom/media/Tracing.cpp:17
(Diff revisions 2 - 7)
>  #include "AsyncLogger.h"
> -#include "Tracing.h"
> +#include "mozilla/TimeStamp.h"
>  
>  using namespace mozilla;
>  
> +AsyncLogger gMSGTraceLogger("MSGTracing");

It seems like Tracing.cpp shouldn't have to be aware of the MSG.

::: dom/media/Tracing.cpp:69
(Diff revisions 2 - 7)
>    : mLogger(aLogger)
>    , mLocation(aLocation)
>    , mEventType(aEventType)
>    , mPID(aPID)
>    , mTID(aTID)
> +	, mLoggerEnabled(mLogger.Enabled())

Indentation looks off.

::: dom/media/Tracing.cpp:92
(Diff revisions 2 - 7)
>    , mLocation(aLocation)
>    , mComment(aComment)
>    , mEventType(aEventType)
>    , mPID(aPID)
>    , mTID(aTID)
> +	, mLoggerEnabled(mLogger.Enabled())

Indentation looks off.

::: dom/media/MediaStreamGraph.cpp:73
(Diff revision 7)
> +#ifdef TRACING
> +  gMSGTraceLogger.Stop();
> +#endif

I think it'd make more sense to define gMSGTraceLogger in this file.
Attachment #8960681 - Flags: review+
Comment on attachment 8960681 [details]
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media.

https://reviewboard.mozilla.org/r/229436/#review236530

> enum class

I'm indexing using the enum value, so I can't make it an enum class.
Comment on attachment 8960681 [details]
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media.

https://reviewboard.mozilla.org/r/229436/#review236530

> I'm indexing using the enum value, so I can't make it an enum class.

You can still `static_cast` such enums to integers, though.  It's a little bit noisier, but perhaps that's worth it for the strong typing guarantees you get?
(In reply to Nathan Froyd [:froydnj] from comment #46)
> Comment on attachment 8960681 [details]
> Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for
> real-time media.
> 
> https://reviewboard.mozilla.org/r/229436/#review236530
> 
> > I'm indexing using the enum value, so I can't make it an enum class.
> 
> You can still `static_cast` such enums to integers, though.  It's a little
> bit noisier, but perhaps that's worth it for the strong typing guarantees
> you get?

Nice, done. Thanks!
Pushed by paul@paul.cx:
https://hg.mozilla.org/integration/autoland/rev/0fa5f7cfee1d
Implement a lock-free asynchronous logging system to be used from real-time audio and video code. r=froydnj
https://hg.mozilla.org/integration/autoland/rev/822a57090d84
Use the AsyncLog to implement a tracing subsystem for real-time media. r=pehrsons
https://hg.mozilla.org/integration/autoland/rev/b021b33ddf74
Trace some initial real-time media stuff. r=pehrsons
Backout by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ab04b1ca218d
Backed out 3 changesets for build bustages on dom/media/AsyncLogger. CLOSED TREE
Pushed by paul@paul.cx:
https://hg.mozilla.org/integration/autoland/rev/2512c9c24244
Implement a lock-free asynchronous logging system to be used from real-time audio and video code. r=froydnj
https://hg.mozilla.org/integration/autoland/rev/35ca96cabe3c
Use the AsyncLog to implement a tracing subsystem for real-time media. r=pehrsons
https://hg.mozilla.org/integration/autoland/rev/79b7ee8b01ee
Trace some initial real-time media stuff. r=pehrsons
Flags: needinfo?(padenot)
Backout by apavel@mozilla.com:
https://hg.mozilla.org/mozilla-central/rev/0e45c13b34e8
Backed out 3 changesets for failing android at dom/media/tests/mochitest/test_getUserMedia_mediaStreamTrackClone.html a=backout
Backed out for failing android at dom/media/tests/mochitest/test_getUserMedia_mediaStreamTrackClone.htm

Push that started the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=79b7ee8b01ee122b3f7122f926e5ae9dc1132a96

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=174276391&repo=autoland&lineNumber=2162

Backout: https://hg.mozilla.org/mozilla-central/rev/0e45c13b34e815cb42a9f08bb44142d1a81e186e
Status: RESOLVED → REOPENED
Flags: needinfo?(padenot)
Resolution: FIXED → ---
status-firefox61: fixed → ---
Target Milestone: mozilla61 → ---
Apparently even simply doing the TimeStamp::now() calls is enough to bust android jobs, they are very close to he limit. I've made those only occur when logging is enabled, it's better regardless.
Flags: needinfo?(padenot)
Pushed by paul@paul.cx:
https://hg.mozilla.org/integration/autoland/rev/c1191a038fc1
Implement a lock-free asynchronous logging system to be used from real-time audio and video code. r=froydnj
https://hg.mozilla.org/integration/autoland/rev/6a9a43e7a081
Use the AsyncLog to implement a tracing subsystem for real-time media. r=pehrsons
https://hg.mozilla.org/integration/autoland/rev/07735bff3717
Trace some initial real-time media stuff. r=pehrsons
https://hg.mozilla.org/mozilla-central/rev/c1191a038fc1
https://hg.mozilla.org/mozilla-central/rev/6a9a43e7a081
https://hg.mozilla.org/mozilla-central/rev/07735bff3717
Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
status-firefox61: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
See Also: → 1460559
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: