I can hear pops and clicks just about every time the score needs to scroll.  I also see from top that chrome is using 100% CPU on my high-powered Z840.

More investigation needed to see what's using the CPU so heavily.

kromatisktkluster@

Can you provide the trace when glitch happens? I tried to reproduce the problem on my MacPro but it rarely glitches. Please be sure to include "audio", "blink_gc" and "webaudio" in the trace category.

@hongchan I've attached the trace, it's between pressing play and about 20 seconds on with the categories you suggested. I did the trace on an i7 Surface Pro 4 and heard maybe 5 - 6 pops. For me chrome averages about 25% cpu and 15% gpu during playback with some visible spikes around garbage collection, I'm not sure if these coincide with the pops though, GC is much more frequent than the glitches.

Deleted: trace_scorecloud.json.gz 1.2 MB

trace_scorecloud.json.gz 1.2 MB Download

I used perf record on the render tab to get some statistics. (Using ToT chromium today).  Some results:

Samples: 117K of event 'cycles:pp', Event count (approx.): 12136085064167
  Children      Self  Command          Shared Object                                       Symbol
-   99.67%     0.00%  TaskSchedulerRe  libbase.so                                          [.] _ZN4base12_GLOBAL__N_110ThreadFuncEPv
   + _ZN4base12_GLOBAL__N_110ThreadFuncEPv
+   99.67%     0.00%  TaskSchedulerRe  libpthread-2.19.so                                  [.] start_thread
+   99.67%     0.00%  TaskSchedulerRe  libbase.so                                          [.] _ZN4base8internal15SchedulerWorker6Thread10ThreadMainEv
+   99.67%     0.00%  TaskSchedulerRe  libbase.so                                          [.] _ZN4base8internal11TaskTracker11RunNextTaskE13scoped_refptrINS0_8SequenceEEPNS0_27CanScheduleSequenceObserverE
+   99.67%     0.00%  TaskSchedulerRe  libbase.so                                          [.] _ZN4base8internal16TaskTrackerPosix13RunOrSkipTaskENS0_4TaskEPNS0_8SequenceEb
+   99.67%     0.00%  TaskSchedulerRe  libbase.so                                          [.] _ZN4base8internal11TaskTracker13RunOrSkipTaskENS0_4TaskEPNS0_8SequenceEb
+   99.67%     0.00%  TaskSchedulerRe  libbase.so                                          [.] _ZN4base5debug13TaskAnnotator7RunTaskEPKcPNS_11PendingTaskE
+   99.66%     0.00%  TaskSchedulerRe  libv8.so                                            [.] _ZN2v88internal15ItemParallelJob4Task11RunInternalEv
+   99.66%     0.00%  TaskSchedulerRe  libv8.so                                            [.] _ZN2v88internal7Sweeper17ParallelSweepPageEPNS0_4PageENS0_15AllocationSpaceE
-   99.66%    99.66%  TaskSchedulerRe  libv8.so                                            [.] _ZN2v88internal7Sweeper8RawSweepEPNS0_4PageENS1_22FreeListRebuildingModeENS0_22FreeSpaceTreatmentModeE
   - 99.66% start_thread
        _ZN4base12_GLOBAL__N_110ThreadFuncEPv
        _ZN4base8internal15SchedulerWorker6Thread10ThreadMainEv
        _ZN4base8internal11TaskTracker11RunNextTaskE13scoped_refptrINS0_8SequenceEEPNS0_27CanScheduleSequenceObserverE
        _ZN4base8internal16TaskTrackerPosix13RunOrSkipTaskENS0_4TaskEPNS0_8SequenceEb
        _ZN4base8internal11TaskTracker13RunOrSkipTaskENS0_4TaskEPNS0_8SequenceEb
      - _ZN4base5debug13TaskAnnotator7RunTaskEPKcPNS_11PendingTaskE
         - 99.66% _ZN2v88internal15ItemParallelJob4Task11RunInternalEv
              _ZN2v88internal18PageEvacuationTask13RunInParallelEv
              _ZN2v88internal9Evacuator12EvacuatePageEPNS0_4PageE
            - _ZN2v88internal13FullEvacuator15RawEvacuatePageEPNS0_4PageEPl
               - 99.66% _ZN2v88internal17LiveObjectVisitor17VisitBlackObjectsINS0_23EvacuateOldSpaceVisitorENS0_26MajorNonAtomicMarkingStateEEEbPNS0_11MemoryChunkEPT0_PT_NS1_13IterationModeEPPNS0_10HeapObjectE
                    _ZN2v88internal14LocalAllocator8AllocateENS0_15AllocationSpaceEiNS0_19AllocationAlignmentE
                    _ZN2v88internal10PagedSpace20AllocateRawUnalignedEiNS1_14UpdateSkipListE
                    _ZN2v88internal10PagedSpace33RawSlowRefillLinearAllocationAreaEi
                    _ZN2v88internal7Sweeper18ParallelSweepSpaceENS0_15AllocationSpaceEii
                    _ZN2v88internal7Sweeper17ParallelSweepPageEPNS0_4PageENS0_15AllocationSpaceE
                    _ZN2v88internal7Sweeper8RawSweepEPNS0_4PageENS1_22FreeListRebuildingModeENS0_22FreeSpaceTreatmentModeE
               - 0.00% _ZN2v88internal17LiveObjectVisitor23VisitBlackObjectsNoFailINS0_23EvacuateNewSpaceVisitorENS0_26MajorNonAtomicMarkingStateEEEvPNS0_11MemoryChunkEPT0_PT_NS1_13IterationModeE
                    _ZN2v88internal23EvacuateNewSpaceVisitor5VisitEPNS0_10HeapObjectEi
                    _ZN2v88internal10PagedSpace20AllocateRawUnalignedEiNS1_14UpdateSkipListE
                    _ZN2v88internal10PagedSpace33RawSlowRefillLinearAllocationAreaEi
                    _ZN2v88internal7Sweeper18ParallelSweepSpaceENS0_15AllocationSpaceEii
                    _ZN2v88internal7Sweeper17ParallelSweepPageEPNS0_4PageENS0_15AllocationSpaceE
                    _ZN2v88internal7Sweeper8RawSweepEPNS0_4PageENS1_22FreeListRebuildingModeENS0_22FreeSpaceTreatmentModeE
         + 0.00% _ZN2v88internal7Sweeper11SweeperTask11RunInternalEv

This indicates lots of GC going on.

Also, using devtools performance, we get:

Self			Total			Activity
2692.3 ms	37.6 %	2748.9 ms	38.4 %  Paint
437.1 ms	6.1 %	1821.2 ms	25.5 %  Timer Fired
148.5 ms	2.1 %	1533.1 ms	21.4 %  Animation Frame Fired

Ideally, if you're just using 10 buffer source nodes with 6 gain nodes, you shouldn't be having any problems with webaudio.  And a great test, if you can do it, is to just try that, without all of the rest of the UI and stuff going on.

The trace file you uploaded shows that there's not very little time spent in the audio thread.

AFAICT, this isn't a webaudio problem.

Once the buffer source nodes are started, do you manipulate the buffer sources or gain nodes in any way?

> Once the buffer source nodes are started, do you manipulate the buffer sources or gain nodes in any way?

@rtoy, Hi. We do set the gain of the gain nodes initially, and when the sliders are clicked. The issue appears even without interaction with the sliders.

This did work with previous versions of Chrome, and there are no problems in any other browsers we're testing.

We seem to get varied results, sometimes less popping, when switching from the tab, witch might suspend the playhead animation that uses animation frame..?

Yes, switching away from the tab will throttle requestAnimationFrames.  But since you still hear pops without switching away, let's ignore that issue.

Grabbed a trace from chrome://tracing.  The AudioOutputDevice thread doesn't appear to be stressed,  There's plenty of time to process the buffers.  I do see on my Linux box that the timings for FireRenderCallback are rather irregular and that could cause audio to glitch if the thread were more loaded.

Deleted: trace_trace-802293.json.gz 6.9 MB

trace_trace-802293.json.gz 6.9 MB Download

We tried disabling all timers, animation frames and any other UI updates. We still get the audio issues, only much less frequently.

We will probably optimize our code to get around this on our site, but there is still an issue with chrome at work here.

olka@

Could you take a look at the trace at #7? The timing of AudioOutputDevice::FireRenderCallback is quite irregular and I am not sure what can cause this problem.

There is no AudioWorklet involved, so WebAudio is being pulled by the AudioOutputDevice synchronously. Seems like the audio infra is struggling for some reason.

FWIW, I ran the repro url on my windows machine and grabbed a trace.  FireRenderCallback is called very regularly on this machine.  

I also don't hear any glitches in the audio but the red score bar is really janky.  But there are no audio glitches.

Chrome  66.0.3346.3 (Official Build) canary SyzyASan (32-bit), Z440 win10.

Deleted: trace_trace-802293-win10.json.gz 2.7 MB

trace_trace-802293-win10.json.gz 2.7 MB Download

Thanks for a fantastic recording in #3.
I see Blink GC eating CPU time and/or blocking AudioDestinationHandler::Render from execution, which leads to missing IPC deadline and a glitch - see an attachment. It happens 8 times throughout the trace.

Deleted: ThreadHeap eats CPU.png 191 KB

	ThreadHeap eats CPU.png 191 KB View Download

keishi@ - I see you've done a lot of work in BlinkGC recently - could you PTAL or reroute?

AudioDestinationHandler::Render runs on a realtime-ish thread which should not be blocked like that.

olka@

Thanks for the update! Just curious: why is it "realtime-ish"? I thought it was realtime priority thread.

It's different on different platforms. Renderer-side thread is real-time on CrOS, high priority on Win, and not sure what it is on Linux. Browser-side is real-time on everywhere except for ALSA.

Do you have an idea what lock it can be waiting on? I'm not familiar with Blink GC.

Another version is it's not waiting, but is just descheduled while GC consumes CPU. But the pattern of glitches seems to be way too stable for that.

The trace results mentioned in c#11 match my perf profile results in c#4.  GC is taking lots of time.

I can't reproduce the issue but judging by the fact that AudioOutputDevice task finishes right after BlinkGCMarking every time in the trace file from c#3, this is most likely a CrossThreadPersistent waiting on locking the ProcessHeap::CrossThreadPersistentMutex(). I've created a CL to crash when a CrossThreadPersistent is taking too much time to acquire the lock. https://chromium-review.googlesource.com/#/c/chromium/src/+/923444 Could someone reproduce the issue with a Debug build with the CL applied and see where it crashes?

The example page https://my.scorecloud.com/song/fb32dab332f95ea93742cca2a957afd0/2097
crashes for me both with and without a patch from #19.
rtoy/hongchan - could you do the test?

I also suspect that the issue would be easier to reproduce on a 2-core device.

Assigning to hongchan@ as webaudio expert.

Oilpan can't get around the fact that CrossThreadPersistent assignments must lock ProcessHeap::CrossThreadPersistentMutex() (i.e. wait on main thread GC) so this issue needs to be worked on from the web audio side.

The bug is marked as a regression - in which Chrome version it worked well?

We (scorecloud.com) started bug error reports from our users 20th of november 2017. We have not tested this case with earlier versions now, but we have tested and evaluated the site regularly since developed, around april 2014, and we havn't seen it or had any error reports during that time.

Could you test the case with M62?

johanronstrom@

I've tested the page in #21 with the latest Canary 67.0.3370.0 on MacOS. I don't hear the glitch anymore. Also the trace doesn't show any anomaly in the AudioOutputDevice thread.

Deleted: Screen Shot 2018-03-14 at 3.32.38 PM.png 59.8 KB

	Screen Shot 2018-03-14 at 3.32.38 PM.png 59.8 KB View Download

Since it has been more than 15 days and we do not have feedback from the developers, I am lowering the priority to P3. I believe this issue is fixed by the recent optimization of BaseAudioContext clean up.

Sorry for not responding earlier. The issue seems to have been resolved, not hearing any glitches in Canary 67.0.3386.0 on Windows 10. Thank you!

Closing per #29.

The NextAction date has arrived: 2018-04-16