1346005 - Add logging for audio frames

Status: RESOLVED FIXED

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

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Attachment: add audio samples-inserted logging using AudioLatency:4

you may want to put some other logging on this module as well

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

Should we log the Desired time as well in MediaPipeline? Or something else we can get from the graph?
 
I would expect this to be used with timestamp,AudioLatency:4

This should allow us to catch gross (user-audible) drifts/delay-buildups especially by looking at totalSamples vs time-elapsed.

Feel free to land this if you're happy with it.

Comment 3

[Paul Adenot (:padenot)]

Comment on attachment 8845751 [details] [diff] [review]
add audio samples-inserted logging using AudioLatency:4

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

r+ with comments addressed.

::: dom/media/webrtc/MediaEngineWebRTCAudio.cpp
@@ +585,5 @@
>      return;
>    }
>  
> +  if (MOZ_LOG_TEST(AudioLogModule(), LogLevel::Debug)) {
> +    mTotalSamples += aFrames;

Change the name of `mTotalSamples` to `mTotalFrames`, since you're accumulating frames.

@@ +588,5 @@
> +  if (MOZ_LOG_TEST(AudioLogModule(), LogLevel::Debug)) {
> +    mTotalSamples += aFrames;
> +    if (mTotalSamples > mLastDebug + mSampleFrequency) { // ~ 1 second
> +      MOZ_LOG(AudioLogModule(), LogLevel::Debug,
> +              ("%p: Inserting %lu samples into graph, totalSamples = %lu", (void*)this,

s/%lu/" PRIu64 "/g

note the space, otherwise it'll break when we'll update compilers.

@@ +590,5 @@
> +    if (mTotalSamples > mLastDebug + mSampleFrequency) { // ~ 1 second
> +      MOZ_LOG(AudioLogModule(), LogLevel::Debug,
> +              ("%p: Inserting %lu samples into graph, totalSamples = %lu", (void*)this,
> +               aFrames, mTotalSamples));
> +      mLastDebug = mTotalSamples;

Make this a bit more descriptive: `mLastLogTime` or something.

::: media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp
@@ +1889,5 @@
>   protected:
>    SourceMediaStream *source_;
>    const TrackID track_id_;
>    TrackTicks played_ticks_;
> +  TrackTicks last_debug_;

same comment about a more descriptive name.

@@ +2021,5 @@
>          played_ticks_ += frames;
> +        if (MOZ_LOG_TEST(AudioLogModule(), LogLevel::Debug)) {
> +          if (played_ticks_ > last_debug_ + rate) { // ~ 1 second
> +            MOZ_LOG(AudioLogModule(), LogLevel::Debug,
> +                    ("%p: Inserting %lu samples into track %d, total = %lu",

s/%d/" PRId64 "/g, and same for the %lu, those are both int64_t numbers. 

nothing worse than having logs you can't trust, heh.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/31656946aa03
add audio samples-inserted logging using AudioLatency:4 r=padenot

Comment 5

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Backed out for bustage in MediaPipeline.cpp:

https://hg.mozilla.org/integration/mozilla-inbound/rev/063241ee73a56c21197031e0b3bbc5d35d9128ac

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=31656946aa0347b5e639e3d3118eddd38008aedf&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=83116541&repo=mozilla-inbound

[task 2017-03-10T20:31:24.638393Z] 20:31:24     INFO -  /home/worker/workspace/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp: In member function 'virtual void mozilla::MediaPipelineReceiveAudio::PipelineListener::NotifyPull(mozilla::MediaStreamGraph*, mozilla::StreamTime)':
[task 2017-03-10T20:31:24.638663Z] 20:31:24     INFO -  /home/worker/workspace/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp:2021:43: error: 'rate' was not declared in this scope
[task 2017-03-10T20:31:24.638843Z] 20:31:24     INFO -             if (played_ticks_ > last_log_ + rate) { // ~ 1 second
[task 2017-03-10T20:31:24.642270Z] 20:31:24     INFO -                                             ^
[task 2017-03-10T20:31:24.642359Z] 20:31:24     INFO -  /home/worker/workspace/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp:2022:166: error: expected ')' before 'PRIuSIZE'
[task 2017-03-10T20:31:24.642407Z] 20:31:24     INFO -               MOZ_LOG(AudioLogModule(), LogLevel::Debug,
[task 2017-03-10T20:31:24.642482Z] 20:31:24     INFO -                                                                                                                                                                        ^
[task 2017-03-10T20:31:24.642556Z] 20:31:24     INFO -  /home/worker/workspace/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp:2022:266: error: spurious trailing '%' in format [-Werror=format=]
[task 2017-03-10T20:31:24.642600Z] 20:31:24     INFO -               MOZ_LOG(AudioLogModule(), LogLevel::Debug,
[task 2017-03-10T20:31:24.642702Z] 20:31:24     INFO -                                                                                                                                                                                                                                                                            ^
[task 2017-03-10T20:31:24.642778Z] 20:31:24     INFO -  /home/worker/workspace/build/src/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp:2022:266: error: too many arguments for format [-Werror=format-extra-args]
[task 2017-03-10T20:31:24.642819Z] 20:31:24     INFO -  cc1plus: all warnings being treated as errors
[task 2017-03-10T20:31:24.642891Z] 20:31:24     INFO -  /home/worker/workspace/build/src/config/rules.mk:1016: recipe for target 'MediaPipeline.o' failed
[task 2017-03-10T20:31:24.642934Z] 20:31:24     INFO -  gmake[5]: *** [MediaPipeline.o] Error 1

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2b23902cadd8
add audio samples-inserted logging using AudioLatency:4 r=padenot

Comment 7

[Iris Hsiao [:ihsiao]]

sorry had to back this out for bustage in MediaPipeline.cpp like https://treeherder.mozilla.org/logviewer.html#?job_id=83314039&repo=mozilla-inbound&lineNumber=14407

https://hg.mozilla.org/integration/mozilla-inbound/rev/3a2b595587f8

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/59ee633c6b81
add audio samples-inserted logging using AudioLatency:4 r=padenot

Comment 9

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/59ee633c6b81

Comment 10

[Jim Jeffery not reading bug-mail 1/2/11]

Maybe I'm missing something, but why does this keep getting pushed without any patch changes after being backed out at least twice now ?

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

There were changes... the initial landing was a mis-merge because the patch was on top of another patch.  The second one was a build failure due to the wonders of unified builds (needed a #include)