Creates a new license request latency metric

Previously, we did not have a license request latency metric. This is a
notable limitation in our metrics. This adds a metric that captures the
timing between a GenerateKeyRequest and an AddKey operation.

Bug: 72994956
Test: New unit tests. Google Play
Change-Id: If99c187399c02f9b5d4c355732af7588bbbefb11

libwvdrmengine/cdm/core/include/cdm_session.h

@@ -199,6 +199,12 @@ class CdmSession {
 
   bool UpdateUsageInfo();
 
+  CdmResponseType GenerateKeyRequestInternal(
+      const InitializationData& init_data, CdmLicenseType license_type,
+      const CdmAppParameterMap& app_parameters, CdmKeyRequest* key_request);
+  virtual CdmResponseType AddKeyInternal(const CdmKeyResponse& key_response);
+  void UpdateRequestLatencyTiming(CdmResponseType sts);
+
   // These setters are for testing only. Takes ownership of the pointers.
   void set_license_parser(CdmLicense* license_parser);
   void set_crypto_session(CryptoSession* crypto_session);
@@ -209,6 +215,8 @@ class CdmSession {
   metrics::SessionMetrics* metrics_;
   metrics::CryptoMetrics* crypto_metrics_;
   metrics::TimerMetric life_span_;
+  metrics::TimerMetric license_request_latency_;
+  CdmKeyRequestType key_request_type_;
 
   bool initialized_;
   bool closed_;  // Session closed, but final shared_ptr has not been released.

libwvdrmengine/cdm/core/src/cdm_session.cpp

@@ -324,7 +324,23 @@ CdmResponseType CdmSession::RestoreUsageSession(
   return KEY_ADDED;
 }
 
+// This is a thin wrapper that initiates the latency metric.
 CdmResponseType CdmSession::GenerateKeyRequest(
+    const InitializationData& init_data, CdmLicenseType license_type,
+    const CdmAppParameterMap& app_parameters, CdmKeyRequest* key_request) {
+  CdmResponseType result = GenerateKeyRequestInternal(
+      init_data, license_type, app_parameters, key_request);
+  // Note that GenerateReleaseRequest and GenerateRenewalRequest will initialize
+  // the timer themselves. This is duplicate because there are duplicate paths
+  // for calling GenerateReleaseRequest and GenerateRenewalRequest.
+  if (result == KEY_MESSAGE) {
+    key_request_type_ = key_request->type;
+    license_request_latency_.Start(); // Start or restart timer.
+  }
+  return result;
+}
+
+CdmResponseType CdmSession::GenerateKeyRequestInternal(
     const InitializationData& init_data, CdmLicenseType license_type,
     const CdmAppParameterMap& app_parameters,
     CdmKeyRequest* key_request) {
@@ -410,8 +426,15 @@ CdmResponseType CdmSession::GenerateKeyRequest(
   }
 }
 
-// AddKey() - Accept license response and extract key info.
+// This thin wrapper allows us to update metrics.
 CdmResponseType CdmSession::AddKey(const CdmKeyResponse& key_response) {
+  CdmResponseType sts = AddKeyInternal(key_response);
+  UpdateRequestLatencyTiming(sts);
+  return sts;
+}
+
+// AddKeyInternal() - Accept license response and extract key info.
+CdmResponseType CdmSession::AddKeyInternal(const CdmKeyResponse& key_response) {
   if (!initialized_) {
     LOGE("CdmSession::AddKey: not initialized");
     return NOT_INITIALIZED_ERROR;
@@ -602,6 +625,8 @@ CdmResponseType CdmSession::GenerateRenewalRequest(
   if (is_offline_) {
     offline_key_renewal_request_ = key_request->message;
   }
+  key_request_type_ = key_request->type;
+  license_request_latency_.Start(); // Start or restart timer.
   return KEY_MESSAGE;
 }
 
@@ -613,6 +638,10 @@ CdmResponseType CdmSession::RenewKey(const CdmKeyResponse& key_response) {
   }
   CdmResponseType sts =
       license_parser_->HandleKeyUpdateResponse(true, key_response);
+
+  // Record the timing on success.
+  UpdateRequestLatencyTiming(sts);
+
   if (sts != KEY_ADDED) return (sts == KEY_ERROR) ? RENEW_KEY_ERROR_1 : sts;
 
   if (is_offline_) {
@@ -630,6 +659,7 @@ CdmResponseType CdmSession::GenerateReleaseRequest(
     return NOT_INITIALIZED_ERROR;
   }
   is_release_ = true;
+  license_request_latency_.Clear();
   CdmResponseType status = license_parser_->PrepareKeyUpdateRequest(
       false, app_parameters_, usage_table_header_ == NULL ? NULL : this,
       &key_request->message, &key_request->url);
@@ -658,6 +688,10 @@ CdmResponseType CdmSession::GenerateReleaseRequest(
         return RELEASE_USAGE_INFO_FAILED;
     }
   }
+
+  key_request_type_ = key_request->type;
+  license_request_latency_.Start(); // Start or restart timer.
+
   return KEY_MESSAGE;
 }
 
@@ -669,6 +703,9 @@ CdmResponseType CdmSession::ReleaseKey(const CdmKeyResponse& key_response) {
   }
   CdmResponseType sts =
       license_parser_->HandleKeyUpdateResponse(false, key_response);
+  // Record the timing on success.
+  UpdateRequestLatencyTiming(sts);
+
   if (sts != KEY_ADDED) return (sts == KEY_ERROR) ? RELEASE_KEY_ERROR : sts;
 
   if (is_offline_ || has_provider_session_token()) {
@@ -1046,6 +1083,14 @@ bool CdmSession::UpdateUsageInfo() {
       usage_data);
 }
 
+void CdmSession::UpdateRequestLatencyTiming(CdmResponseType sts) {
+  if (sts == KEY_ADDED && license_request_latency_.IsStarted()) {
+    metrics_->cdm_session_license_request_latency_ms_.Record(
+        license_request_latency_.AsMs(), key_request_type_);
+  }
+  license_request_latency_.Clear();
+}
+
 // For testing only - takes ownership of pointers
 
 void CdmSession::set_license_parser(CdmLicense* license_parser) {

libwvdrmengine/cdm/core/test/cdm_engine_test.cpp

@@ -15,6 +15,7 @@
 #include "file_store.h"
 #include "license_request.h"
 #include "log.h"
+#include "metrics.pb.h"
 #include "OEMCryptoCENC.h"
 #include "properties.h"
 #include "scoped_ptr.h"
@@ -26,6 +27,9 @@
 
 namespace wvcdm {
 
+using drm_metrics::WvCdmMetrics;
+using drm_metrics::DistributionMetric;
+
 namespace {
 
 // Http OK response code.
@@ -460,12 +464,43 @@ class WvCdmEngineTest : public WvCdmEnginePreProvTest {
     CdmKeySetId key_set_id;
     EXPECT_EQ(KEY_ADDED,
               cdm_engine_.AddKey(session_id_, resp, &key_set_id));
+    VerifyLicenseRequestLatency(CdmKeyRequestType::kKeyRequestTypeInitial,
+                                *cdm_engine_.GetMetrics());
   }
 
   void VerifyRenewalKeyResponse(const std::string& server_url,
                                 const std::string& client_auth) {
     std::string resp = GetKeyRequestResponse(server_url, client_auth);
     EXPECT_EQ(KEY_ADDED, cdm_engine_.RenewKey(session_id_, resp));
+    VerifyLicenseRequestLatency(CdmKeyRequestType::kKeyRequestTypeRenewal,
+                                *cdm_engine_.GetMetrics());
+  }
+
+  void VerifyLicenseRequestLatency(
+      CdmKeyRequestType key_request_type,
+      const metrics::EngineMetrics& engine_metrics) {
+    WvCdmMetrics metrics_proto;
+    engine_metrics.Serialize(&metrics_proto);
+    bool has_request_type = false;
+    for (int i = 0; i < metrics_proto.session_metrics_size(); i++) {
+      WvCdmMetrics::SessionMetrics session_metrics =
+          metrics_proto.session_metrics(i);
+      for (int j = 0;
+           j < session_metrics.cdm_session_license_request_latency_ms_size();
+           j++) {
+        DistributionMetric latency_distribution =
+            session_metrics.cdm_session_license_request_latency_ms(j);
+        if (latency_distribution.attributes().key_request_type()
+            == key_request_type && latency_distribution.operation_count() > 0) {
+          has_request_type = true;
+        }
+      }
+    }
+    std::string serialized_metrics;
+    ASSERT_TRUE(metrics_proto.SerializeToString(&serialized_metrics));
+    EXPECT_TRUE(has_request_type)
+        << "Expected request type " << key_request_type << " was not found. "
+        << "metrics: " << wvcdm::b2a_hex(serialized_metrics);
   }
 
   std::string server_url_;

libwvdrmengine/cdm/metrics/include/counter_metric.h

@@ -106,7 +106,7 @@ class CounterMetric : public BaseCounterMetric {
   }
 
   void ToProto(::google::protobuf::RepeatedPtrField<drm_metrics::CounterMetric>
-                   *counters);
+                   *counters) const;
 
  private:
   friend class CounterMetricTest;
@@ -121,7 +121,7 @@ template <>
 inline void CounterMetric<0, util::Unused, 0, util::Unused, 0, util::Unused, 0,
                           util::Unused>::
     ToProto(::google::protobuf::RepeatedPtrField<drm_metrics::CounterMetric>
-                *counters) {
+                *counters) const {
 
   const std::map<std::string, int64_t>* values = GetValues();
   for (std::map<std::string, int64_t>::const_iterator it = values->begin();
@@ -135,7 +135,7 @@ template <int I1, typename F1, int I2, typename F2, int I3, typename F3, int I4,
           typename F4>
 inline void CounterMetric<I1, F1, I2, F2, I3, F3, I4, F4>::ToProto(
     ::google::protobuf::RepeatedPtrField<drm_metrics::CounterMetric>
-        *counters) {
+        *counters) const {
   const std::map<std::string, int64_t>* values = GetValues();
   for (std::map<std::string, int64_t>::const_iterator it = values->begin();
        it != values->end(); it++) {

libwvdrmengine/cdm/metrics/include/event_metric.h

@@ -110,7 +110,7 @@ class EventMetric : public BaseEventMetric {
 
   void ToProto(
       ::google::protobuf::RepeatedPtrField<drm_metrics::DistributionMetric>
-          *distributions_proto);
+          *distributions_proto) const;
 
  private:
   friend class EventMetricTest;
@@ -118,7 +118,7 @@ class EventMetric : public BaseEventMetric {
 
   inline void SetDistributionValues(
       const Distribution &distribution,
-      drm_metrics::DistributionMetric *metric_proto) {
+      drm_metrics::DistributionMetric *metric_proto) const {
     metric_proto->set_mean(distribution.Mean());
     metric_proto->set_operation_count(distribution.Count());
     if (distribution.Count() > 1) {
@@ -140,7 +140,7 @@ inline void EventMetric<0, util::Unused, 0, util::Unused, 0, util::Unused, 0,
                         util::Unused>::
     ToProto(
         ::google::protobuf::RepeatedPtrField<drm_metrics::DistributionMetric>
-            *distributions_proto) {
+            *distributions_proto) const {
   const std::map<std::string, Distribution *>* distributions
       = GetDistributions();
   for (std::map<std::string, Distribution *>::const_iterator it =
@@ -154,7 +154,7 @@ template <int I1, typename F1, int I2, typename F2, int I3, typename F3, int I4,
           typename F4>
 inline void EventMetric<I1, F1, I2, F2, I3, F3, I4, F4>::ToProto(
     ::google::protobuf::RepeatedPtrField<drm_metrics::DistributionMetric>
-        *distributions_proto) {
+        *distributions_proto) const {
   const std::map<std::string, Distribution *>* distributions
       = GetDistributions();
   for (std::map<std::string, Distribution *>::const_iterator it =

libwvdrmengine/cdm/metrics/include/metrics_collections.h

@@ -82,6 +82,8 @@ const int kKeyStatusTypeFieldNumber =
     ::drm_metrics::Attributes::kKeyStatusTypeFieldNumber;
 const int kEventTypeFieldNumber =
     ::drm_metrics::Attributes::kEventTypeFieldNumber;
+const int kKeyRequestTypeFieldNumber =
+    ::drm_metrics::Attributes::kKeyRequestTypeFieldNumber;
 
 }  // anonymous namespace
 
@@ -111,7 +113,8 @@ typedef enum OEMCryptoInitializationMode {
 // This class contains metrics for Crypto Session and OEM Crypto.
 class CryptoMetrics {
  public:
-  void Serialize(drm_metrics::WvCdmMetrics::CryptoMetrics *crypto_metrics);
+  void Serialize(drm_metrics::WvCdmMetrics::CryptoMetrics *crypto_metrics)
+      const;
 
   /* CRYPTO SESSION */
   // TODO(blueeyes): Convert this to crypto_session_default_security_level_.
@@ -267,13 +270,17 @@ class SessionMetrics {
   CounterMetric<kErrorCodeFieldNumber, CdmResponseType>
       cdm_session_restore_usage_session_;
 
+  EventMetric<kKeyRequestTypeFieldNumber, CdmKeyRequestType>
+      cdm_session_license_request_latency_ms_;
+
   // Serialize the session metrics to the provided |metric_group|.
   // |metric_group| is owned by the caller and must not be null.
-  void Serialize(drm_metrics::WvCdmMetrics::SessionMetrics *session_metrics);
+  void Serialize(drm_metrics::WvCdmMetrics::SessionMetrics *session_metrics)
+      const;
 
  private:
   void SerializeSessionMetrics(
-      drm_metrics::WvCdmMetrics::SessionMetrics *session_metrics);
+      drm_metrics::WvCdmMetrics::SessionMetrics *session_metrics) const;
   CdmSessionId session_id_;
   bool completed_;
   CryptoMetrics crypto_metrics_;
@@ -299,13 +306,14 @@ class OemCryptoDynamicAdapterMetrics {
 
   // Serialize the session metrics to the provided |metric_group|.
   // |metric_group| is owned by the caller and must not be null.
-  void Serialize(drm_metrics::WvCdmMetrics::EngineMetrics *engine_metrics);
+  void Serialize(drm_metrics::WvCdmMetrics::EngineMetrics *engine_metrics)
+      const;
 
   // Clears the existing metric values.
   void Clear();
 
  private:
-  Lock adapter_lock_;
+  mutable Lock adapter_lock_;
   ValueMetric<OEMCryptoInitializationMode> oemcrypto_initialization_mode_;
   ValueMetric<uint32_t> oemcrypto_l1_api_version_;
   ValueMetric<uint32_t> oemcrypto_l1_min_api_version_;
@@ -351,7 +359,7 @@ class EngineMetrics {
   // void Serialize(drm_metrics::MetricsGroup* metric_group, bool
   // completed_only,
   //               bool clear_serialized_sessions);
-  void Serialize(drm_metrics::WvCdmMetrics *engine_metrics);
+  void Serialize(drm_metrics::WvCdmMetrics *engine_metrics) const;
 
   void SetAppPackageName(const std::string &app_package_name);
 
@@ -397,7 +405,7 @@ class EngineMetrics {
       cdm_engine_unprovision_;
 
  private:
-  Lock session_metrics_lock_;
+  mutable Lock session_metrics_lock_;
   std::vector<metrics::SessionMetrics *> session_metrics_list_;
   // This is used to populate the engine lifespan metric
   metrics::TimerMetric life_span_internal_;
@@ -405,7 +413,7 @@ class EngineMetrics {
   std::string app_package_name_;
 
   void SerializeEngineMetrics(
-      drm_metrics::WvCdmMetrics::EngineMetrics *engine_metrics);
+      drm_metrics::WvCdmMetrics::EngineMetrics *engine_metrics) const;
 };
 
 }  // namespace metrics

libwvdrmengine/cdm/metrics/include/timer_metric.h

@@ -9,13 +9,23 @@ namespace metrics {
 class TimerMetric {
 
  public:
+  // Starts the clock running. If the clock was previously set, this resets it.
+  // IsStarted will return true after this call.
   void Start();
+  // Returns whether or not the timer has started.
+  bool IsStarted() const { return is_started_; };
+  // Stops the clock and clears the current value.  IsStarted will return false
+  // after this call.
+  void Clear();
+  // Returns the current clock value as milliseconds (AsMs) or microseconds
+  // (AsUs).
   double AsMs() const;
   double AsUs() const;
 
  private:
   double sec_;
   double usec_;
+  bool is_started_;
 
 };
 

libwvdrmengine/cdm/metrics/include/value_metric.h

@@ -72,7 +72,7 @@ class ValueMetric {
 
   // Returns a new ValueMetric proto containing the metric value or the
   // error code. If neither the error or value are set, it returns nullptr.
-  drm_metrics::ValueMetric *ToProto() {
+  drm_metrics::ValueMetric *ToProto() const {
     if (has_error_) {
       drm_metrics::ValueMetric *value_proto = new drm_metrics::ValueMetric;
       value_proto->set_error_code(error_code_);

libwvdrmengine/cdm/metrics/src/attribute_handler.cpp

@@ -72,6 +72,14 @@ void SetAttributeField<drm_metrics::Attributes::kSigningAlgorithmFieldNumber,
   attributes->set_signing_algorithm(signing_algorithm);
 }
 
+template <>
+void SetAttributeField<drm_metrics::Attributes::kKeyRequestTypeFieldNumber,
+                       CdmKeyRequestType>(
+    const CdmKeyRequestType &key_request_type,
+    drm_metrics::Attributes *attributes) {
+  attributes->set_key_request_type(key_request_type);
+}
+
 template <>
 void SetAttributeField<0, util::Unused>(const util::Unused &,
                                         drm_metrics::Attributes *) {

libwvdrmengine/cdm/metrics/src/metrics.proto

@@ -44,6 +44,8 @@ message Attributes {
   optional uint32 key_status_type = 14;
   // Defined at ::android::hardware::drm::V1_0::EventType;
   optional uint32 event_type = 15;
+  // Contains the CdmKeyRequestType defined in wv_cdm_types.h.
+  optional uint32 key_request_type = 16;
 }
 
 // The Counter message is used to store a count value with an associated
@@ -153,7 +155,7 @@ message WvCdmMetrics {
 
   // This contains metrics that were captured within a CdmSession. This contains
   // nested CryptoMetrics that were captured in the context of the session.
-  // next id: 7
+  // next id: 8
   message SessionMetrics {
     optional ValueMetric session_id = 1;
     optional CryptoMetrics crypto_metrics = 2;
@@ -161,6 +163,7 @@ message WvCdmMetrics {
     repeated DistributionMetric cdm_session_renew_key_time_us = 4;
     repeated CounterMetric cdm_session_restore_offline_session = 5;
     repeated CounterMetric cdm_session_restore_usage_session = 6;
+    repeated DistributionMetric cdm_session_license_request_latency_ms = 7;
   }
 
   // These are metrics recorded at the Engine level. This includes CryptoSession

libwvdrmengine/cdm/metrics/src/metrics_collections.cpp

@@ -29,7 +29,8 @@ struct CompareSessionIds {
 namespace wvcdm {
 namespace metrics {
 
-void CryptoMetrics::Serialize(WvCdmMetrics::CryptoMetrics *crypto_metrics) {
+void CryptoMetrics::Serialize(WvCdmMetrics::CryptoMetrics *crypto_metrics)
+    const {
   /* CRYPTO SESSION */
   crypto_metrics->set_allocated_crypto_session_security_level(
       crypto_session_security_level_.ToProto());
@@ -151,20 +152,16 @@ void CryptoMetrics::Serialize(WvCdmMetrics::CryptoMetrics *crypto_metrics) {
             crypto_metrics->mutable_oemcrypto_update_usage_entry());
 }
 
-SessionMetrics::SessionMetrics()
+SessionMetrics::SessionMetrics() {}
-    : cdm_session_life_span_(),
-      cdm_session_renew_key_(),
-      cdm_session_restore_offline_session_(),
-      cdm_session_restore_usage_session_(),
-      completed_(false) {}
 
-void SessionMetrics::Serialize(WvCdmMetrics::SessionMetrics *session_metrics) {
+void SessionMetrics::Serialize(WvCdmMetrics::SessionMetrics *session_metrics)
+    const {
   SerializeSessionMetrics(session_metrics);
   crypto_metrics_.Serialize(session_metrics->mutable_crypto_metrics());
 }
 
 void SessionMetrics::SerializeSessionMetrics(
-    WvCdmMetrics::SessionMetrics *session_metrics) {
+    WvCdmMetrics::SessionMetrics *session_metrics) const {
   // If the session id was set, add it to the metrics. It's possible that
   // it's not set in some circumstances such as when provisioning is needed.
   if (!session_id_.empty()) {
@@ -178,6 +175,8 @@ void SessionMetrics::SerializeSessionMetrics(
       session_metrics->mutable_cdm_session_restore_offline_session());
   cdm_session_restore_usage_session_.ToProto(
       session_metrics->mutable_cdm_session_restore_usage_session());
+  cdm_session_license_request_latency_ms_.ToProto(
+      session_metrics->mutable_cdm_session_license_request_latency_ms());
 }
 
 OemCryptoDynamicAdapterMetrics::OemCryptoDynamicAdapterMetrics()
@@ -202,7 +201,7 @@ void OemCryptoDynamicAdapterMetrics::SetL1MinApiVersion(uint32_t version) {
 }
 
 void OemCryptoDynamicAdapterMetrics::Serialize(
-    WvCdmMetrics::EngineMetrics *engine_metrics) {
+    WvCdmMetrics::EngineMetrics *engine_metrics) const {
   AutoLock lock(adapter_lock_);
 
   engine_metrics->set_allocated_oemcrypto_initialization_mode(
@@ -264,7 +263,7 @@ void EngineMetrics::RemoveSession(wvcdm::CdmSessionId session_id) {
       session_metrics_list_.end());
 }
 
-void EngineMetrics::Serialize(WvCdmMetrics *wv_metrics) {
+void EngineMetrics::Serialize(WvCdmMetrics *wv_metrics) const {
   AutoLock lock(session_metrics_lock_);
   WvCdmMetrics::EngineMetrics *engine_metrics =
       wv_metrics->mutable_engine_metrics();
@@ -291,7 +290,7 @@ void EngineMetrics::SetAppPackageName(const std::string &app_package_name) {
 }
 
 void EngineMetrics::SerializeEngineMetrics(
-    WvCdmMetrics::EngineMetrics *engine_metrics) {
+    WvCdmMetrics::EngineMetrics *engine_metrics) const {
   // Set the engine lifespan at the time of serialization.
   engine_metrics->mutable_cdm_engine_life_span_ms()->set_int_value(
       life_span_internal_.AsMs());

libwvdrmengine/cdm/metrics/src/timer_metric.cpp

@@ -11,6 +11,13 @@ void TimerMetric::Start() {
   gettimeofday(&tv, NULL);
   sec_ = tv.tv_sec;
   usec_ = tv.tv_usec;
+  is_started_ = true;
+}
+
+void TimerMetric::Clear() {
+  is_started_ = false;
+  sec_ = 0;
+  usec_ = 0;
 }
 
 double TimerMetric::AsMs() const {