Merge pull request #4476 from bazsi/loggen-performance-improvements

news/feature-4476.md

@@ -0,0 +1,2 @@
+`loggen`: improve loggen performance for synthetic workloads, so we can test
+up to 650k msg/sec on my AMD Ryzen 7 Pro 6850U CPU.

tests/loggen/loggen.c

@@ -137,7 +137,9 @@ generate_message(char *buffer, int buffer_size, ThreadData *thread_context, unsi
   if (read_from_file)
     str_len = read_next_message_from_file(buffer, buffer_size, syslog_proto, thread_context->index);
   else
-    str_len = generate_log_line(buffer, buffer_size, syslog_proto, thread_context->index, seq);
+    str_len = generate_log_line(thread_context,
+                                buffer, buffer_size,
+                                syslog_proto, thread_context->index, global_plugin_option.rate, seq);
 
   if (str_len < 0)
     return -1;
@@ -396,11 +398,17 @@ print_statistic(struct timeval *start_time)
 {
   gint64 count;
   static gint64 last_count = 0;
-  static struct timeval last_ts_format;
+  static struct timeval last_ts_format = {0};
 
   struct timeval now;
   gettimeofday(&now, NULL);
 
+  if (!last_ts_format.tv_sec)
+    {
+      last_ts_format = now;
+      return;
+    }
+
   if (!quiet && !csv)
     {
       guint64 diff_usec = time_val_diff_in_usec(&now, &last_ts_format);
@@ -410,7 +418,7 @@ print_statistic(struct timeval *start_time)
           count = sent_messages_num;
           g_mutex_unlock(&message_counter_lock);
 
-          if (count > last_count && last_count > 0)
+          if (count > last_count)
             {
               fprintf(stderr, "count=%"G_GINT64_FORMAT", rate = %.2lf msg/sec\n",
                       count,

tests/loggen/loggen_plugin.c

@@ -42,6 +42,19 @@ thread_check_exit_criteria(ThreadData *thread_context)
       return TRUE;
     }
 
+  long seq_check;
+
+  /* 0.1 sec */
+  seq_check = thread_context->option->rate / 10;
+
+  /* or every 1000 messages */
+  if (seq_check > 1000)
+    seq_check = 1000;
+
+
+  if (seq_check > 1 && (thread_context->sent_messages % seq_check) != 0)
+    return FALSE;
+
   struct timeval now;
   gettimeofday(&now, NULL);
 
@@ -59,28 +72,30 @@ gboolean
 thread_check_time_bucket(ThreadData *thread_context)
 {
   struct timeval now;
+
+  if (thread_context->buckets > 0)
+    return FALSE;
+
   gettimeofday(&now, NULL);
 
   double diff_usec = time_val_diff_in_usec(&now, &thread_context->last_throttle_check);
-  if (thread_context->buckets == 0 || diff_usec > 1e5)
+  long new_buckets = (long)((thread_context->option->rate * diff_usec) / USEC_PER_SEC);
+  if (new_buckets)
     {
-      /* check rate every 0.1sec */
-      long new_buckets = (long)((thread_context->option->rate * diff_usec) / USEC_PER_SEC);
-      if (new_buckets)
-        {
-          thread_context->buckets = (thread_context->option->rate < thread_context->buckets + new_buckets) ?
-                                    thread_context->option->rate : thread_context->buckets + new_buckets;
-          thread_context->last_throttle_check = now;
-        }
+      thread_context->buckets = (thread_context->option->rate < thread_context->buckets + new_buckets) ?
+                                thread_context->option->rate : thread_context->buckets + new_buckets;
+      thread_context->last_throttle_check = now;
     }
 
   if (thread_context->buckets == 0)
     {
       struct timespec tspec;
-      long msec = (1000 / thread_context->option->rate) + 1;
 
-      tspec.tv_sec = msec / 1000;
-      tspec.tv_nsec = (msec % 1000) * 1000000;
+      /* wait at least 3 messages worth of time but not more than 1s */
+      tspec.tv_sec = 0;
+      tspec.tv_nsec = 3 * (1000000000LL / thread_context->option->rate);
+      if (tspec.tv_nsec >= 100000000)
+        tspec.tv_nsec = 100000000;
       while (nanosleep(&tspec, &tspec) < 0 && errno == EINTR)
         ;
       return TRUE;

tests/loggen/loggen_plugin.h

@@ -62,6 +62,10 @@ typedef struct _thread_data
   struct timeval last_throttle_check;
   long buckets;
   gboolean proxy_header_sent;
+
+  /* timestamp  cache for logline generator */
+  struct timeval ts_formatted;
+  char stamp[32];
 } ThreadData;
 
 typedef GOptionEntry *(*get_option_func)(void);

tests/loggen/logline_generator.c

@@ -23,6 +23,7 @@
 
 #include "logline_generator.h"
 #include "loggen_helper.h"
+#include "loggen_plugin.h"
 
 #include <stdio.h>
 #include <string.h>
@@ -97,7 +98,12 @@ prepare_log_line_template(int syslog_proto, int framing, int message_length, cha
 }
 
 int
-generate_log_line(char *buffer, int buffer_length, int syslog_proto, int thread_id, unsigned long seq)
+generate_log_line(ThreadData *thread_context,
+                  char *buffer, int buffer_length,
+                  int syslog_proto,
+                  int thread_id,
+                  unsigned long rate,
+                  unsigned long seq)
 {
   if (!buffer)
     {
@@ -110,17 +116,28 @@ generate_log_line(char *buffer, int buffer_length, int syslog_proto, int thread_
 
   /* create time stamps */
   struct timeval now;
-  gettimeofday(&now, NULL);
   struct tm tm;
-  char stamp[32];
-  localtime_r(&now.tv_sec, &tm);
-  int len = strftime(stamp, sizeof(stamp), "%Y-%m-%dT%H:%M:%S", &tm);
-  memcpy(&buffer[pos_timestamp2], stamp, len);
+  static int len;
 
-  if (syslog_proto)
-    format_timezone_offset_with_colon(stamp, sizeof(stamp), &tm);
+  int check_seq = rate / 10;
+  if (check_seq > 1000)
+    check_seq = 1000;
+  if (check_seq <= 1 || (seq % check_seq) == 0)
+    {
+      gettimeofday(&now, NULL);
+      if (now.tv_sec != thread_context->ts_formatted.tv_sec)
+        {
+          localtime_r(&now.tv_sec, &tm);
+          len = strftime(thread_context->stamp, sizeof(thread_context->stamp), "%Y-%m-%dT%H:%M:%S", &tm);
+          thread_context->ts_formatted = now;
+
+          if (syslog_proto)
+            format_timezone_offset_with_colon(thread_context->stamp, sizeof(thread_context->stamp), &tm);
+        }
+    }
 
-  memcpy(&buffer[pos_timestamp1], stamp, strlen(stamp));
+  memcpy(&buffer[pos_timestamp2], thread_context->stamp, len);
+  memcpy(&buffer[pos_timestamp1], thread_context->stamp, strlen(thread_context->stamp));
 
   /* print sequence number to logline */
   char intbuf[16];

tests/loggen/logline_generator.h

@@ -24,7 +24,14 @@
 #ifndef LOGLINE_GENERATOR_H_INCLUDED
 #define LOGLINE_GENERATOR_H_INCLUDED
 
-int generate_log_line(char *buffer, int buffer_length, int syslog_proto, int thread_id, unsigned long seq);
+#include "loggen_plugin.h"
+
+int generate_log_line(ThreadData *thread_context,
+                      char *buffer, int buffer_length,
+                      int syslog_proto,
+                      int thread_id,
+                      unsigned long rate,
+                      unsigned long seq);
 int prepare_log_line_template(int syslog_proto, int framing, int message_length, char *sdata_value);
 
 #endif