sync_reader.cc 15 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398
  1. // Copyright (c) 2012 The Chromium Authors. All rights reserved.
  2. // Use of this source code is governed by a BSD-style license that can be
  3. // found in the LICENSE file.
  4. #include "services/audio/sync_reader.h"
  5. #include <algorithm>
  6. #include <limits>
  7. #include <string>
  8. #include <utility>
  9. #include "base/command_line.h"
  10. #include "base/format_macros.h"
  11. #include "base/logging.h"
  12. #include "base/metrics/histogram_functions.h"
  13. #include "base/numerics/safe_conversions.h"
  14. #include "base/strings/strcat.h"
  15. #include "base/strings/stringprintf.h"
  16. #include "base/trace_event/trace_event.h"
  17. #include "build/build_config.h"
  18. #include "build/chromeos_buildflags.h"
  19. #include "media/audio/audio_device_thread.h"
  20. #include "media/base/audio_parameters.h"
  21. #include "media/base/media_switches.h"
  22. using media::AudioLatency;
  23. namespace {
  24. // Used to log if any audio glitches have been detected during an audio session.
  25. // Elements in this enum should not be added, deleted or rearranged.
  26. enum class AudioGlitchResult {
  27. kNoGlitches = 0,
  28. kGlitches = 1,
  29. kMaxValue = kGlitches
  30. };
  31. void LogPerLatencyGlitchUma(AudioLatency::LatencyType latency,
  32. int renderer_missed_callback_count,
  33. int renderer_callback_count,
  34. bool mixing) {
  35. DCHECK_LE(renderer_missed_callback_count, renderer_callback_count);
  36. auto LatencyToString = [](AudioLatency::LatencyType latency) {
  37. switch (latency) {
  38. case AudioLatency::LATENCY_EXACT_MS:
  39. return "LatencyExactMs";
  40. case AudioLatency::LATENCY_INTERACTIVE:
  41. return "LatencyInteractive";
  42. case AudioLatency::LATENCY_RTC:
  43. return "LatencyRtc";
  44. case AudioLatency::LATENCY_PLAYBACK:
  45. return "LatencyPlayback";
  46. default:
  47. return "LatencyUnknown";
  48. }
  49. };
  50. const std::string suffix = LatencyToString(latency);
  51. if (!mixing) {
  52. base::UmaHistogramEnumeration("Media.AudioRendererAudioGlitches2." + suffix,
  53. (renderer_missed_callback_count > 0)
  54. ? AudioGlitchResult::kGlitches
  55. : AudioGlitchResult::kNoGlitches);
  56. }
  57. const int kPermilleScaling = 1000;
  58. // 10%: if we have more that 10% of callbacks having issues, the details are
  59. // not very interesting any more, so we just log all those cases together to
  60. // have a better resolution for lower values.
  61. const int kHistogramRange = kPermilleScaling / 10;
  62. // 30 s for 10 ms buffers (RTC streams)/ 1 minute for 20 ms buffers (media
  63. // playback).
  64. const int kShortStreamMaxCallbackCount = 3000;
  65. if (renderer_callback_count <= 0)
  66. return;
  67. int missed_permille = std::ceil(
  68. kPermilleScaling * static_cast<double>(renderer_missed_callback_count) /
  69. renderer_callback_count);
  70. std::string histogram_name = base::StrCat(
  71. {"Media.AudioRendererMissedDeadline2.", mixing ? "Mixing." : "",
  72. (renderer_callback_count < kShortStreamMaxCallbackCount) ? "Short"
  73. : "Long"});
  74. base::UmaHistogramCustomCounts(histogram_name,
  75. std::min(missed_permille, kHistogramRange), 0,
  76. kHistogramRange + 1, 100);
  77. base::UmaHistogramCustomCounts(histogram_name + "." + suffix,
  78. std::min(missed_permille, kHistogramRange), 0,
  79. kHistogramRange + 1, 100);
  80. }
  81. } // namespace
  82. namespace audio {
  83. #if !BUILDFLAG(IS_MAC) && !BUILDFLAG(IS_CHROMEOS_ASH) && \
  84. !BUILDFLAG(IS_CHROMEOS_LACROS)
  85. const base::Feature kDynamicAudioTimeout{"DynamicAudioTimeout",
  86. base::FEATURE_ENABLED_BY_DEFAULT};
  87. const base::FeatureParam<double> kBufferDurationPercent{
  88. &kDynamicAudioTimeout, "buffer_duration_percent", 0.95};
  89. #endif
  90. SyncReader::SyncReader(
  91. base::RepeatingCallback<void(const std::string&)> log_callback,
  92. const media::AudioParameters& params,
  93. base::CancelableSyncSocket* foreign_socket)
  94. : log_callback_(std::move(log_callback)),
  95. latency_tag_(params.latency_tag()),
  96. mute_audio_for_testing_(base::CommandLine::ForCurrentProcess()->HasSwitch(
  97. switches::kMuteAudio)),
  98. output_bus_buffer_size_(
  99. media::AudioBus::CalculateMemorySize(params.channels(),
  100. params.frames_per_buffer())) {
  101. #if BUILDFLAG(IS_MAC) || BUILDFLAG(IS_CHROMEOS_ASH) || \
  102. BUILDFLAG(IS_CHROMEOS_LACROS)
  103. maximum_wait_time_ = params.GetBufferDuration() / 2;
  104. maximum_wait_time_for_mixing_ = maximum_wait_time_;
  105. #else
  106. if (base::FeatureList::IsEnabled(kDynamicAudioTimeout)) {
  107. maximum_wait_time_ =
  108. params.GetBufferDuration() * kBufferDurationPercent.Get();
  109. } else {
  110. maximum_wait_time_ = base::Milliseconds(20);
  111. }
  112. maximum_wait_time_for_mixing_ = maximum_wait_time_;
  113. #if BUILDFLAG(CHROME_WIDE_ECHO_CANCELLATION)
  114. if (base::FeatureList::IsEnabled(media::kChromeWideEchoCancellation)) {
  115. double mixing_timeout_percent =
  116. media::kChromeWideEchoCancellationDynamicMixingTimeout.Get();
  117. // The default negative value means we should ignore this parameter.
  118. if (mixing_timeout_percent > 0) {
  119. maximum_wait_time_for_mixing_ =
  120. params.GetBufferDuration() * mixing_timeout_percent;
  121. }
  122. }
  123. #endif
  124. #endif
  125. base::CheckedNumeric<size_t> memory_size =
  126. media::ComputeAudioOutputBufferSizeChecked(params);
  127. if (!memory_size.IsValid())
  128. return;
  129. shared_memory_region_ =
  130. base::UnsafeSharedMemoryRegion::Create(memory_size.ValueOrDie());
  131. shared_memory_mapping_ = shared_memory_region_.Map();
  132. if (shared_memory_region_.IsValid() && shared_memory_mapping_.IsValid() &&
  133. base::CancelableSyncSocket::CreatePair(&socket_, foreign_socket)) {
  134. auto* const buffer = reinterpret_cast<media::AudioOutputBuffer*>(
  135. shared_memory_mapping_.memory());
  136. output_bus_ = media::AudioBus::WrapMemory(params, buffer->audio);
  137. output_bus_->Zero();
  138. output_bus_->set_is_bitstream_format(params.IsBitstreamFormat());
  139. }
  140. }
  141. SyncReader::~SyncReader() {
  142. DCHECK_GE(renderer_callback_count_, mixing_renderer_callback_count_);
  143. if (!renderer_callback_count_)
  144. return;
  145. // Subtract 'trailing' count of callbacks missed just before the destructor
  146. // call. This happens if the renderer process was killed or e.g. the page
  147. // refreshed while the output device was open etc.
  148. // This trims off the end of both the missed and total counts so that we
  149. // preserve the proportion of counts before the teardown period.
  150. DCHECK_LE(trailing_renderer_missed_callback_count_,
  151. renderer_missed_callback_count_);
  152. DCHECK_LE(trailing_renderer_missed_callback_count_, renderer_callback_count_);
  153. renderer_missed_callback_count_ -= trailing_renderer_missed_callback_count_;
  154. renderer_callback_count_ -= trailing_renderer_missed_callback_count_;
  155. DCHECK_LE(mixing_trailing_renderer_missed_callback_count_,
  156. mixing_renderer_missed_callback_count_);
  157. DCHECK_LE(mixing_trailing_renderer_missed_callback_count_,
  158. mixing_renderer_callback_count_);
  159. mixing_renderer_missed_callback_count_ -=
  160. mixing_trailing_renderer_missed_callback_count_;
  161. mixing_renderer_callback_count_ -=
  162. mixing_trailing_renderer_missed_callback_count_;
  163. DCHECK_GE(renderer_callback_count_, mixing_renderer_callback_count_);
  164. if (!renderer_callback_count_)
  165. return;
  166. base::UmaHistogramEnumeration("Media.AudioRendererAudioGlitches",
  167. (renderer_missed_callback_count_ > 0)
  168. ? AudioGlitchResult::kGlitches
  169. : AudioGlitchResult::kNoGlitches);
  170. int percentage_missed =
  171. 100.0 * renderer_missed_callback_count_ / renderer_callback_count_;
  172. base::UmaHistogramPercentage("Media.AudioRendererMissedDeadline",
  173. percentage_missed);
  174. LogPerLatencyGlitchUma(latency_tag_, renderer_missed_callback_count_,
  175. renderer_callback_count_, /*mixing=*/false);
  176. LogPerLatencyGlitchUma(latency_tag_, mixing_renderer_missed_callback_count_,
  177. mixing_renderer_callback_count_, /*mixing=*/true);
  178. TRACE_EVENT_INSTANT1("audio", "~SyncReader", TRACE_EVENT_SCOPE_THREAD,
  179. "Missed callback percentage", percentage_missed);
  180. log_callback_.Run(base::StringPrintf(
  181. "ASR: number of detected audio glitches: %" PRIuS " out of %" PRIuS,
  182. renderer_missed_callback_count_, renderer_callback_count_));
  183. }
  184. bool SyncReader::IsValid() const {
  185. if (output_bus_) {
  186. DCHECK(shared_memory_region_.IsValid());
  187. DCHECK(shared_memory_mapping_.IsValid());
  188. DCHECK_NE(socket_.handle(), base::SyncSocket::kInvalidHandle);
  189. return true;
  190. }
  191. return false;
  192. }
  193. base::UnsafeSharedMemoryRegion SyncReader::TakeSharedMemoryRegion() {
  194. return std::move(shared_memory_region_);
  195. }
  196. // AudioOutputController::SyncReader implementations.
  197. void SyncReader::RequestMoreData(base::TimeDelta delay,
  198. base::TimeTicks delay_timestamp,
  199. int prior_frames_skipped) {
  200. // We don't send arguments over the socket since sending more than 4
  201. // bytes might lead to being descheduled. The reading side will zero
  202. // them when consumed.
  203. auto* const buffer = reinterpret_cast<media::AudioOutputBuffer*>(
  204. shared_memory_mapping_.memory());
  205. // Increase the number of skipped frames stored in shared memory.
  206. buffer->params.frames_skipped += prior_frames_skipped;
  207. buffer->params.delay_us = delay.InMicroseconds();
  208. buffer->params.delay_timestamp_us =
  209. (delay_timestamp - base::TimeTicks()).InMicroseconds();
  210. // Zero out the entire output buffer to avoid stuttering/repeating-buffers
  211. // in the anomalous case if the renderer is unable to keep up with real-time.
  212. output_bus_->Zero();
  213. uint32_t control_signal = 0;
  214. if (delay.is_max()) {
  215. // std::numeric_limits<uint32_t>::max() is a special signal which is
  216. // returned after the browser stops the output device in response to a
  217. // renderer side request.
  218. control_signal = std::numeric_limits<uint32_t>::max();
  219. }
  220. size_t sent_bytes = socket_.Send(&control_signal, sizeof(control_signal));
  221. if (sent_bytes != sizeof(control_signal)) {
  222. // Ensure we don't log consecutive errors as this can lead to a large
  223. // amount of logs.
  224. if (!had_socket_error_) {
  225. had_socket_error_ = true;
  226. static const char* socket_send_failure_message =
  227. "ASR: No room in socket buffer.";
  228. PLOG(WARNING) << socket_send_failure_message;
  229. log_callback_.Run(socket_send_failure_message);
  230. TRACE_EVENT_INSTANT0("audio", socket_send_failure_message,
  231. TRACE_EVENT_SCOPE_THREAD);
  232. }
  233. } else {
  234. had_socket_error_ = false;
  235. }
  236. ++buffer_index_;
  237. }
  238. void SyncReader::Read(media::AudioBus* dest, bool is_mixing) {
  239. ++renderer_callback_count_;
  240. if (is_mixing)
  241. ++mixing_renderer_callback_count_;
  242. if (!WaitUntilDataIsReady(is_mixing)) {
  243. ++trailing_renderer_missed_callback_count_;
  244. ++renderer_missed_callback_count_;
  245. if (is_mixing) {
  246. ++mixing_trailing_renderer_missed_callback_count_;
  247. ++mixing_renderer_missed_callback_count_;
  248. }
  249. if (renderer_missed_callback_count_ <= 100 &&
  250. renderer_missed_callback_count_ % 10 == 0) {
  251. LOG(WARNING) << "SyncReader::Read timed out, audio glitch count="
  252. << renderer_missed_callback_count_;
  253. if (renderer_missed_callback_count_ == 100)
  254. LOG(WARNING) << "(log cap reached, suppressing further logs)";
  255. }
  256. dest->Zero();
  257. return;
  258. }
  259. trailing_renderer_missed_callback_count_ = 0;
  260. mixing_trailing_renderer_missed_callback_count_ = 0;
  261. // Zeroed buffers may be discarded immediately when outputing compressed
  262. // bitstream.
  263. if (mute_audio_for_testing_ && !output_bus_->is_bitstream_format()) {
  264. dest->Zero();
  265. return;
  266. }
  267. if (output_bus_->is_bitstream_format()) {
  268. // For bitstream formats, we need the real data size and PCM frame count.
  269. auto* const buffer = reinterpret_cast<media::AudioOutputBuffer*>(
  270. shared_memory_mapping_.memory());
  271. uint32_t data_size = buffer->params.bitstream_data_size;
  272. uint32_t bitstream_frames = buffer->params.bitstream_frames;
  273. // |bitstream_frames| is cast to int below, so it must fit.
  274. if (data_size > output_bus_buffer_size_ ||
  275. !base::IsValueInRangeForNumericType<int>(bitstream_frames)) {
  276. // Received data doesn't fit in the buffer, shouldn't happen.
  277. dest->Zero();
  278. return;
  279. }
  280. output_bus_->SetBitstreamDataSize(data_size);
  281. output_bus_->SetBitstreamFrames(bitstream_frames);
  282. output_bus_->CopyTo(dest);
  283. return;
  284. }
  285. // Copy and clip data coming across the shared memory since it's untrusted.
  286. output_bus_->CopyAndClipTo(dest);
  287. }
  288. void SyncReader::Close() {
  289. socket_.Close();
  290. output_bus_.reset();
  291. }
  292. bool SyncReader::WaitUntilDataIsReady(bool is_mixing) {
  293. TRACE_EVENT0("audio", "SyncReader::WaitUntilDataIsReady");
  294. base::TimeDelta timeout =
  295. is_mixing ? maximum_wait_time_for_mixing_ : maximum_wait_time_;
  296. const base::TimeTicks start_time = base::TimeTicks::Now();
  297. const base::TimeTicks finish_time = start_time + timeout;
  298. // Check if data is ready and if not, wait a reasonable amount of time for it.
  299. //
  300. // Data readiness is achieved via parallel counters, one on the renderer side
  301. // and one here. Every time a buffer is requested via UpdatePendingBytes(),
  302. // |buffer_index_| is incremented. Subsequently every time the renderer has a
  303. // buffer ready it increments its counter and sends the counter value over the
  304. // SyncSocket. Data is ready when |buffer_index_| matches the counter value
  305. // received from the renderer.
  306. //
  307. // The counter values may temporarily become out of sync if the renderer is
  308. // unable to deliver audio fast enough. It's assumed that the renderer will
  309. // catch up at some point, which means discarding counter values read from the
  310. // SyncSocket which don't match our current buffer index.
  311. size_t bytes_received = 0;
  312. uint32_t renderer_buffer_index = 0;
  313. while (timeout.InMicroseconds() > 0) {
  314. bytes_received = socket_.ReceiveWithTimeout(
  315. &renderer_buffer_index, sizeof(renderer_buffer_index), timeout);
  316. if (bytes_received != sizeof(renderer_buffer_index)) {
  317. bytes_received = 0;
  318. break;
  319. }
  320. if (renderer_buffer_index == buffer_index_)
  321. break;
  322. // Reduce the timeout value as receives succeed, but aren't the right index.
  323. timeout = finish_time - base::TimeTicks::Now();
  324. }
  325. // Receive timed out or another error occurred. Receive can timeout if the
  326. // renderer is unable to deliver audio data within the allotted time.
  327. if (!bytes_received || renderer_buffer_index != buffer_index_) {
  328. TRACE_EVENT_INSTANT0("audio", "SyncReader::Read timed out",
  329. TRACE_EVENT_SCOPE_THREAD);
  330. base::TimeDelta time_since_start = base::TimeTicks::Now() - start_time;
  331. base::UmaHistogramCustomTimes("Media.AudioOutputControllerDataNotReady",
  332. time_since_start, base::Milliseconds(1),
  333. base::Milliseconds(1000), 50);
  334. return false;
  335. }
  336. return true;
  337. }
  338. } // namespace audio