audio: Improve logging in remote submix module

Implement IModule::dump to display the current state in
the audioflinger dump.

Throttle repetitive logging when there is nothing to read.

Remove stale comment for already fixed b/307586684.

Bug: 307586684
Test: adb shell dumpsys media.audio_flinger
Change-Id: I1f1f6e1658d035d46af3a933a825b20a78c7f297

audio/aidl/default/include/core-impl/ModuleRemoteSubmix.h

@@ -57,7 +57,7 @@ class ModuleRemoteSubmix : public Module {
     ndk::ScopedAStatus onMasterVolumeChanged(float volume) override;
     int32_t getNominalLatencyMs(
             const ::aidl::android::media::audio::common::AudioPortConfig& portConfig) override;
-    // TODO(b/307586684): Report proper minimum stream buffer size by overriding 'setAudioPatch'.
+    binder_status_t dump(int fd, const char** args, uint32_t numArgs) override;
 };
 
 }  // namespace aidl::android::hardware::audio::core

audio/aidl/default/include/core-impl/StreamRemoteSubmix.h

@@ -67,6 +67,7 @@ class StreamRemoteSubmix : public StreamCommonImpl {
     int64_t mStartTimeNs = 0;
     long mFramesSinceStart = 0;
     int mReadErrorCount = 0;
+    int mReadFailureCount = 0;
 };
 
 class StreamInRemoteSubmix final : public StreamIn, public StreamSwitcher {

audio/aidl/default/r_submix/ModuleRemoteSubmix.cpp

@@ -16,6 +16,7 @@
 
 #define LOG_TAG "AHAL_ModuleRemoteSubmix"
 
+#include <stdio.h>
 #include <vector>
 
 #include <android-base/logging.h>
@@ -174,4 +175,9 @@ int32_t ModuleRemoteSubmix::getNominalLatencyMs(const AudioPortConfig&) {
     return kMinLatencyMs;
 }
 
+binder_status_t ModuleRemoteSubmix::dump(int fd, const char** /*args*/, uint32_t /*numArgs*/) {
+    dprintf(fd, "\nSubmixRoutes:\n%s\n", r_submix::SubmixRoute::dumpRoutes().c_str());
+    return STATUS_OK;
+}
+
 }  // namespace aidl::android::hardware::audio::core

audio/aidl/default/r_submix/StreamRemoteSubmix.cpp

@@ -267,6 +267,7 @@ size_t StreamRemoteSubmix::getStreamPipeSizeInFrames() {
         }
         return ::android::OK;
     }
+    mReadErrorCount = 0;
 
     LOG(VERBOSE) << __func__ << ": " << mDeviceAddress.toString() << ", " << frameCount
                  << " frames";
@@ -294,7 +295,12 @@ size_t StreamRemoteSubmix::getStreamPipeSizeInFrames() {
         }
     }
     if (actuallyRead < frameCount) {
-        LOG(WARNING) << __func__ << ": read " << actuallyRead << " vs. requested " << frameCount;
+        if (++mReadFailureCount < kMaxReadFailureAttempts) {
+            LOG(WARNING) << __func__ << ": read " << actuallyRead << " vs. requested " << frameCount
+                         << " (not all errors will be logged)";
+        }
+    } else {
+        mReadFailureCount = 0;
     }
     mCurrentRoute->updateReadCounterFrames(*actualFrameCount);
     return ::android::OK;

audio/aidl/default/r_submix/SubmixRoute.cpp

@@ -14,6 +14,8 @@
  * limitations under the License.
  */
 
+#include <mutex>
+
 #define LOG_TAG "AHAL_SubmixRoute"
 #include <android-base/logging.h>
 #include <media/AidlConversionCppNdk.h>
@@ -28,10 +30,11 @@ using aidl::android::media::audio::common::AudioDeviceAddress;
 namespace aidl::android::hardware::audio::core::r_submix {
 
 // static
-SubmixRoute::RoutesMonitor SubmixRoute::getRoutes() {
+SubmixRoute::RoutesMonitor SubmixRoute::getRoutes(bool tryLock) {
     static std::mutex submixRoutesLock;
     static RoutesMap submixRoutes;
-    return RoutesMonitor(submixRoutesLock, submixRoutes);
+    return !tryLock ? RoutesMonitor(submixRoutesLock, submixRoutes)
+                    : RoutesMonitor(submixRoutesLock, submixRoutes, tryLock);
 }
 
 // static
@@ -66,6 +69,21 @@ void SubmixRoute::removeRoute(const AudioDeviceAddress& deviceAddress) {
     getRoutes()->erase(deviceAddress);
 }
 
+// static
+std::string SubmixRoute::dumpRoutes() {
+    auto routes = getRoutes(true /*tryLock*/);
+    std::string result;
+    if (routes->empty()) result.append(" <Empty>");
+    for (const auto& r : *(routes.operator->())) {
+        result.append(" - ")
+                .append(r.first.toString())
+                .append(": ")
+                .append(r.second->dump())
+                .append("\n");
+    }
+    return result;
+}
+
 // Verify a submix input or output stream can be opened.
 bool SubmixRoute::isStreamConfigValid(bool isInput, const AudioConfig& streamConfig) {
     // If the stream is already open, don't open it again.
@@ -258,4 +276,23 @@ void SubmixRoute::exitStandby(bool isInput) {
     }
 }
 
+std::string SubmixRoute::dump() NO_THREAD_SAFETY_ANALYSIS {
+    const bool isLocked = mLock.try_lock();
+    std::string result = std::string(isLocked ? "" : "! ")
+                                 .append("Input ")
+                                 .append(mStreamInOpen ? "open" : "closed")
+                                 .append(mStreamInStandby ? ", standby" : ", active")
+                                 .append(", refcount: ")
+                                 .append(std::to_string(mInputRefCount))
+                                 .append(", framesRead: ")
+                                 .append(mSource ? std::to_string(mSource->framesRead()) : "<null>")
+                                 .append("; Output ")
+                                 .append(mStreamOutOpen ? "open" : "closed")
+                                 .append(mStreamOutStandby ? ", standby" : ", active")
+                                 .append(", framesWritten: ")
+                                 .append(mSink ? std::to_string(mSink->framesWritten()) : "<null>");
+    if (isLocked) mLock.unlock();
+    return result;
+}
+
 }  // namespace aidl::android::hardware::audio::core::r_submix

audio/aidl/default/r_submix/SubmixRoute.h

@@ -17,6 +17,7 @@
 #pragma once
 
 #include <mutex>
+#include <string>
 
 #include <android-base/thread_annotations.h>
 #include <audio_utils/clock.h>
@@ -68,6 +69,7 @@ class SubmixRoute {
             const ::aidl::android::media::audio::common::AudioDeviceAddress& deviceAddress);
     static void removeRoute(
             const ::aidl::android::media::audio::common::AudioDeviceAddress& deviceAddress);
+    static std::string dumpRoutes();
 
     bool isStreamInOpen() {
         std::lock_guard guard(mLock);
@@ -115,20 +117,24 @@ class SubmixRoute {
     void standby(bool isInput);
     long updateReadCounterFrames(size_t frameCount);
 
+    std::string dump();
+
   private:
     using RoutesMap = std::map<::aidl::android::media::audio::common::AudioDeviceAddress,
                                std::shared_ptr<r_submix::SubmixRoute>>;
     class RoutesMonitor {
       public:
         RoutesMonitor(std::mutex& mutex, RoutesMap& routes) : mLock(mutex), mRoutes(routes) {}
+        RoutesMonitor(std::mutex& mutex, RoutesMap& routes, bool /*tryLock*/)
+            : mLock(mutex, std::try_to_lock), mRoutes(routes) {}
         RoutesMap* operator->() { return &mRoutes; }
 
       private:
-        std::lock_guard<std::mutex> mLock;
+        std::unique_lock<std::mutex> mLock;
         RoutesMap& mRoutes;
     };
 
-    static RoutesMonitor getRoutes();
+    static RoutesMonitor getRoutes(bool tryLock = false);
 
     bool isStreamConfigCompatible(const AudioConfig& streamConfig);