Remove unflushed events warning when trx metadata is enabled on SBR

Summary:
mysqlbinlog expects rows_query event only in RBR. It prints an
unflushed event warning when it parses a transaction which has rows_query but
not a rows events with STMT_END_F flag set. Since there is no direct way to
tell the binlog format in mysqlbinlog, we'll just forgo the warning for
rows_event which contain metadata.

Reference Patch: facebook/mysql-5.6@89e1c03ac

Reviewed By: lloyd

Differential Revision: D10054923

-----------------------------------------------------------------------

optimize Rows_query_log_event::has_trx_meta_data()

Summary:
Rows_query_log_event::has_trx_meta_data() is expensive as it does a bunch
of string manipulation to figure out if it is prepended by
TRX_META_DATA. In a random profile, it shows to take up 2.7% CPU cycles on
secondaries. The function is called multiple times from different
places during applying a trx from worker threads:
1. Rows_query_log_event::do_apply_event(): The 'apply' of this event
stashes the trx_meta_data_json into 'rli' _only_ if the event contains
trx_meta_data. This is the first invocation of
Rows_query_log_event::has_trx_meta_data()
2. Query_log_event::do_apply_event(): It needs to cleanup
the 'rows_query_ev' stashed in 'rli' _only_ if it has trx_meta_data.
Hence it calls Rows_query_log_event::has_trx_metadata() again
3. Log_event::apply_event(): This extracts the timestamp (for
'milli-secs behind master' calculation) from
trx_meta_data (stashed inside rli in #1) and needs to check if the event
contains trx_meta_data. Hence it calls
Rows_query_log_event::has_trx_metadata() again

It is best to cache this information in the event itself so that the cost
of Rows_query_log_event::has_trx_metadata() is paid only once. This
reduces the cost of this method by 3x.

In a subsequent diff, I intend to cache the result of
Query_log_event::extract_trx_metadata() since this method is also called
multiple times and it is expensive as it does a bunch of json parsing
and string construction/manipulation.

Reviewed By: abhinav04sharma

Differential Revision: D31373879

client/mysqlbinlog.cc

@@ -1905,7 +1905,14 @@ static Exit_status process_event(PRINT_EVENT_INFO *print_event_info,
         }
 
         ev->print(result_file, print_event_info);
-        print_event_info->have_unflushed_events = true;
+
+        // case: we can have rows_query event containing trx metadata in SBR, to
+        // avoid unflushed event warning we'll skip setting this flag when the
+        // rows_query event contains trx metadata
+        if (!(ev_type == binary_log::ROWS_QUERY_LOG_EVENT &&
+              static_cast<Rows_query_log_event *>(ev)->has_trx_meta_data())) {
+          print_event_info->have_unflushed_events = true;
+        }
         /* Flush head,body and footer cache to result_file */
         if (stmt_end) {
           print_event_info->have_unflushed_events = false;

sql/log_event.h

@@ -3640,6 +3640,7 @@ class Ignorable_log_event : public virtual binary_log::Ignorable_event,
   B_l : namespace binary_log
   @endinternal
 */
+const std::string TRX_META_DATA_HEADER = "::TRX_META_DATA::";
 class Rows_query_log_event : public Ignorable_log_event,
                              public binary_log::Rows_query_event {
  public:
@@ -3682,6 +3683,37 @@ class Rows_query_log_event : public Ignorable_log_event,
     return Binary_log_event::IGNORABLE_HEADER_LEN + 1 + strlen(m_rows_query);
   }
 
+  // enum to detect if this event has trx_meta_data prepended to the rows_query
+  enum enum_has_trx_meta_data {
+    UNKNOWN = 0,  // Status not known
+    YES = 1,      // This event contains trx_meta_data
+    NO = 2        // This event does not contain trx_meta_data
+  };
+
+  bool has_trx_meta_data() const {
+    // Return status if we have already decoded and computed it
+    if (has_trx_meta_data_flag != enum_has_trx_meta_data::UNKNOWN) {
+      return has_trx_meta_data_flag == enum_has_trx_meta_data::YES;
+    }
+
+    std::string str(m_rows_query);
+    if (str.length() < (2 + TRX_META_DATA_HEADER.length() + 2)) return false;
+    // NOTE: Meta data comment format: /*::TRX_META_DATA::{.. JSON ..}*/
+    // so to check if the event contains trx meta data we check if the string
+    // "::TRX_META_DATA::" is present after the first two "/*" characters.
+    bool contains_trx_metadata = str.compare(2, TRX_META_DATA_HEADER.length(),
+                                             TRX_META_DATA_HEADER) == 0;
+
+    // Store the result for future use
+    if (contains_trx_metadata) {
+      has_trx_meta_data_flag = enum_has_trx_meta_data::YES;
+    } else {
+      has_trx_meta_data_flag = enum_has_trx_meta_data::NO;
+    }
+
+    return contains_trx_metadata;
+  }
+
  private:
   /*
    * Returns the length of comment at the start of the query.
@@ -3694,6 +3726,11 @@ class Rows_query_log_event : public Ignorable_log_event,
    * @return  comment length.
    */
   uint get_comment_length(const char *str, uint length) const;
+
+  // Flag indicating if this rows-query event has a trx_meta_data prepended to
+  // itself
+  mutable enum_has_trx_meta_data has_trx_meta_data_flag =
+      enum_has_trx_meta_data::UNKNOWN;
 };
 
 static inline bool copy_event_cache_to_file_and_reinit(IO_CACHE *cache,