Improve performance of encoding binary strings

Thanks to @josevalim for suggestion ❤️

Author: AndrewDryga

bench/logger_json_overhead.exs

@@ -0,0 +1,109 @@
+# now = DateTime.utc_now()
+
+inputs = [
+  {"just a msg", %{message: "This is just some elaborate message"}},
+  {"some map",
+   %{
+     message: "some other weirdo message",
+     time: DateTime.utc_now(),
+     http_meta: %{
+       status: 500,
+       method: "GET",
+       headers: [["what", "eva"], ["some-more", "stuff"]]
+     }
+   }},
+  {"bigger_map",
+   %{
+     "users" => %{
+       "user_1" => %{
+         "name" => "Alice",
+         "age" => 30,
+         "preferences" => %{
+           "theme" => "dark",
+           "language" => "English",
+           "notifications" => %{
+             "email" => true,
+             "sms" => false,
+             "push" => true
+           }
+         },
+         "tags" => ["developer", "team_lead"]
+       },
+       "user_2" => %{
+         "name" => "Bob",
+         "age" => 25,
+         "preferences" => %{
+           "theme" => "light",
+           "language" => "French",
+           "notifications" => %{
+             "email" => true,
+             "sms" => true,
+             "push" => false
+           }
+         },
+         "tags" => ["designer", "remote"]
+       }
+     },
+     "settings" => %{
+       "global" => %{
+         "timezone" => "UTC",
+         "currency" => :usd,
+         "support_contact" => "support@example.com"
+       },
+       "regional" => %{
+         "US" => %{
+           "timezone" => "America/New_York",
+           "currency" => :usd
+         },
+         "EU" => %{
+           "timezone" => "Europe/Berlin",
+           "currency" => "EUR"
+         }
+       }
+     },
+     "analytics" => %{
+       "page_views" => %{
+         "home" => 1200,
+         "about" => 450,
+         "contact" => 300
+       },
+       "user_sessions" => %{
+         "total" => 2000,
+         "active" => 150
+       }
+     }
+   }}
+]
+
+redactors = []
+{_, default_formatter_config} = Logger.Formatter.new(colors: [enabled?: false])
+{_, default_json_formatter_config} = LoggerJSON.Formatters.Basic.new(metadata: :all)
+
+Benchee.run(
+  %{
+    "just Jason" => fn input -> Jason.encode_to_iodata!(input) end,
+    "logger_json encode" => fn input ->
+      %{message: LoggerJSON.Formatter.RedactorEncoder.encode(input, redactors)}
+    end,
+    "whole logger format" => fn input ->
+      LoggerJSON.Formatters.Basic.format(%{level: :info, meta: %{}, msg: {:report, input}}, default_json_formatter_config)
+    end,
+    # odd that those 2 end up being the slowest - what additional work are they doing?
+    "default formatter with report data (sanity check)" => fn input ->
+      Logger.Formatter.format(
+        %{level: :info, meta: %{}, msg: {:report, input}},
+        default_formatter_config
+      )
+    end,
+    "default formatter with pre-formatted report data  as string (sanity check 2)" =>
+      {fn input ->
+         Logger.Formatter.format(
+           %{level: :info, meta: %{}, msg: {:string, input}},
+           default_formatter_config
+         )
+       end, before_scenario: &inspect/1}
+  },
+  warmup: 0.1,
+  time: 1,
+  inputs: inputs
+)

lib/logger_json/formatter/redactor_encoder.ex

@@ -87,13 +87,17 @@ defmodule LoggerJSON.Formatter.RedactorEncoder do
   defp format_mfa({module, function, arity}), do: "#{module}.#{function}/#{arity}"
 
   defp encode_binary(data) when is_binary(data) do
-    if String.valid?(data) && String.printable?(data) do
+    if String.printable?(data) do
       data
     else
       inspect(data)
     end
   end
 
+  defp redact(_key, value, []) do
+    value
+  end
+
   defp redact(key, value, redactors) do
     Enum.reduce(redactors, value, fn {redactor, opts}, acc ->
       redactor.redact(to_string(key), acc, opts)

mix.exs

@@ -40,6 +40,7 @@ defmodule LoggerJSON.Mixfile do
       {:decimal, ">= 0.0.0", optional: true},
       {:ecto, "~> 3.11", optional: true},
       {:telemetry, "~> 1.0", optional: true},
+      {:benchee, "~> 1.3", only: [:dev, :test]},
       {:stream_data, "~> 1.0", only: [:dev, :test]},
       {:castore, "~> 1.0", only: [:dev, :test]},
       {:excoveralls, ">= 0.15.0", only: [:dev, :test]},

mix.lock

@@ -1,6 +1,8 @@
 %{
+  "benchee": {:hex, :benchee, "1.3.1", "c786e6a76321121a44229dde3988fc772bca73ea75170a73fd5f4ddf1af95ccf", [:mix], [{:deep_merge, "~> 1.0", [hex: :deep_merge, repo: "hexpm", optional: false]}, {:statistex, "~> 1.0", [hex: :statistex, repo: "hexpm", optional: false]}, {:table, "~> 0.1.0", [hex: :table, repo: "hexpm", optional: true]}], "hexpm", "76224c58ea1d0391c8309a8ecbfe27d71062878f59bd41a390266bf4ac1cc56d"},
   "castore": {:hex, :castore, "1.0.12", "053f0e32700cbec356280c0e835df425a3be4bc1e0627b714330ad9d0f05497f", [:mix], [], "hexpm", "3dca286b2186055ba0c9449b4e95b97bf1b57b47c1f2644555879e659960c224"},
   "decimal": {:hex, :decimal, "2.3.0", "3ad6255aa77b4a3c4f818171b12d237500e63525c2fd056699967a3e7ea20f62", [:mix], [], "hexpm", "a4d66355cb29cb47c3cf30e71329e58361cfcb37c34235ef3bf1d7bf3773aeac"},
+  "deep_merge": {:hex, :deep_merge, "1.0.0", "b4aa1a0d1acac393bdf38b2291af38cb1d4a52806cf7a4906f718e1feb5ee961", [:mix], [], "hexpm", "ce708e5f094b9cd4e8f2be4f00d2f4250c4095be93f8cd6d018c753894885430"},
   "dialyxir": {:hex, :dialyxir, "1.4.5", "ca1571ac18e0f88d4ab245f0b60fa31ff1b12cbae2b11bd25d207f865e8ae78a", [:mix], [{:erlex, ">= 0.2.7", [hex: :erlex, repo: "hexpm", optional: false]}], "hexpm", "b0fb08bb8107c750db5c0b324fa2df5ceaa0f9307690ee3c1f6ba5b9eb5d35c3"},
   "earmark_parser": {:hex, :earmark_parser, "1.4.44", "f20830dd6b5c77afe2b063777ddbbff09f9759396500cdbe7523efd58d7a339c", [:mix], [], "hexpm", "4778ac752b4701a5599215f7030989c989ffdc4f6df457c5f36938cc2d2a2750"},
   "ecto": {:hex, :ecto, "3.12.5", "4a312960ce612e17337e7cefcf9be45b95a3be6b36b6f94dfb3d8c361d631866", [:mix], [{:decimal, "~> 2.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "6eb18e80bef8bb57e17f5a7f068a1719fbda384d40fc37acb8eb8aeca493b6ea"},
@@ -16,6 +18,7 @@
   "nimble_parsec": {:hex, :nimble_parsec, "1.4.2", "8efba0122db06df95bfaa78f791344a89352ba04baedd3849593bfce4d0dc1c6", [:mix], [], "hexpm", "4b21398942dda052b403bbe1da991ccd03a053668d147d53fb8c4e0efe09c973"},
   "plug": {:hex, :plug, "1.17.0", "a0832e7af4ae0f4819e0c08dd2e7482364937aea6a8a997a679f2cbb7e026b2e", [:mix], [{:mime, "~> 1.0 or ~> 2.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.1.1 or ~> 1.2 or ~> 2.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4.3 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "f6692046652a69a00a5a21d0b7e11fcf401064839d59d6b8787f23af55b1e6bc"},
   "plug_crypto": {:hex, :plug_crypto, "2.1.1", "19bda8184399cb24afa10be734f84a16ea0a2bc65054e23a62bb10f06bc89491", [:mix], [], "hexpm", "6470bce6ffe41c8bd497612ffde1a7e4af67f36a15eea5f921af71cf3e11247c"},
+  "statistex": {:hex, :statistex, "1.0.0", "f3dc93f3c0c6c92e5f291704cf62b99b553253d7969e9a5fa713e5481cd858a5", [:mix], [], "hexpm", "ff9d8bee7035028ab4742ff52fc80a2aa35cece833cf5319009b52f1b5a86c27"},
   "stream_data": {:hex, :stream_data, "1.2.0", "58dd3f9e88afe27dc38bef26fce0c84a9e7a96772b2925c7b32cd2435697a52b", [:mix], [], "hexpm", "eb5c546ee3466920314643edf68943a5b14b32d1da9fe01698dc92b73f89a9ed"},
   "telemetry": {:hex, :telemetry, "1.3.0", "fedebbae410d715cf8e7062c96a1ef32ec22e764197f70cda73d82778d61e7a2", [:rebar3], [], "hexpm", "7015fc8919dbe63764f4b4b87a95b7c0996bd539e0d499be6ec9d7f3875b79e6"},
 }