From 89a7efab69d905cc3521388b1e1cf43851848627 Mon Sep 17 00:00:00 2001 From: rinpatch Date: Fri, 11 Sep 2020 14:22:54 +0300 Subject: [PATCH] ConnectionPool: Log possible HTTP1 blocks --- lib/pleroma/gun/conn.ex | 12 ++++++------ lib/pleroma/gun/connection_pool/worker.ex | 22 ++++++++++++++++------ lib/pleroma/telemetry/logger.ex | 18 ++++++++++++++++-- 3 files changed, 38 insertions(+), 14 deletions(-) diff --git a/lib/pleroma/gun/conn.ex b/lib/pleroma/gun/conn.ex index 75b1ffc0a..477e19c6e 100644 --- a/lib/pleroma/gun/conn.ex +++ b/lib/pleroma/gun/conn.ex @@ -50,10 +50,10 @@ defp do_open(uri, %{proxy: {proxy_host, proxy_port}} = opts) do with open_opts <- Map.delete(opts, :tls_opts), {:ok, conn} <- Gun.open(proxy_host, proxy_port, open_opts), - {:ok, _} <- Gun.await_up(conn, opts[:connect_timeout]), + {:ok, protocol} <- Gun.await_up(conn, opts[:connect_timeout]), stream <- Gun.connect(conn, connect_opts), {:response, :fin, 200, _} <- Gun.await(conn, stream) do - {:ok, conn} + {:ok, conn, protocol} else error -> Logger.warn( @@ -88,8 +88,8 @@ defp do_open(uri, %{proxy: {proxy_type, proxy_host, proxy_port}} = opts) do |> Map.put(:socks_opts, socks_opts) with {:ok, conn} <- Gun.open(proxy_host, proxy_port, opts), - {:ok, _} <- Gun.await_up(conn, opts[:connect_timeout]) do - {:ok, conn} + {:ok, protocol} <- Gun.await_up(conn, opts[:connect_timeout]) do + {:ok, conn, protocol} else error -> Logger.warn( @@ -106,8 +106,8 @@ defp do_open(%URI{host: host, port: port} = uri, opts) do host = Pleroma.HTTP.AdapterHelper.parse_host(host) with {:ok, conn} <- Gun.open(host, port, opts), - {:ok, _} <- Gun.await_up(conn, opts[:connect_timeout]) do - {:ok, conn} + {:ok, protocol} <- Gun.await_up(conn, opts[:connect_timeout]) do + {:ok, conn, protocol} else error -> Logger.warn( diff --git a/lib/pleroma/gun/connection_pool/worker.ex b/lib/pleroma/gun/connection_pool/worker.ex index c36332817..49d41e4c7 100644 --- a/lib/pleroma/gun/connection_pool/worker.ex +++ b/lib/pleroma/gun/connection_pool/worker.ex @@ -15,7 +15,7 @@ def init([_key, _uri, _opts, _client_pid] = opts) do @impl true def handle_continue({:connect, [key, uri, opts, client_pid]}, _) do - with {:ok, conn_pid} <- Gun.Conn.open(uri, opts), + with {:ok, conn_pid, protocol} <- Gun.Conn.open(uri, opts), Process.link(conn_pid) do time = :erlang.monotonic_time(:millisecond) @@ -27,8 +27,12 @@ def handle_continue({:connect, [key, uri, opts, client_pid]}, _) do send(client_pid, {:conn_pid, conn_pid}) {:noreply, - %{key: key, timer: nil, client_monitors: %{client_pid => Process.monitor(client_pid)}}, - :hibernate} + %{ + key: key, + timer: nil, + client_monitors: %{client_pid => Process.monitor(client_pid)}, + protocol: protocol + }, :hibernate} else err -> {:stop, {:shutdown, err}, nil} @@ -53,14 +57,20 @@ def handle_cast({:remove_client, client_pid}, state) do end @impl true - def handle_call(:add_client, {client_pid, _}, %{key: key} = state) do + def handle_call(:add_client, {client_pid, _}, %{key: key, protocol: protocol} = state) do time = :erlang.monotonic_time(:millisecond) - {{conn_pid, _, _, _}, _} = + {{conn_pid, used_by, _, _}, _} = Registry.update_value(@registry, key, fn {conn_pid, used_by, crf, last_reference} -> {conn_pid, [client_pid | used_by], crf(time - last_reference, crf), time} end) + :telemetry.execute( + [:pleroma, :connection_pool, :client, :add], + %{client_pid: client_pid, clients: used_by}, + %{key: state.key, protocol: protocol} + ) + state = if state.timer != nil do Process.cancel_timer(state[:timer]) @@ -131,7 +141,7 @@ def handle_info({:gun_down, _pid, _protocol, _reason, _killed_streams}, state) d @impl true def handle_info({:DOWN, _ref, :process, pid, reason}, state) do :telemetry.execute( - [:pleroma, :connection_pool, :client_death], + [:pleroma, :connection_pool, :client, :dead], %{client_pid: pid, reason: reason}, %{key: state.key} ) diff --git a/lib/pleroma/telemetry/logger.ex b/lib/pleroma/telemetry/logger.ex index 4cacae02f..197b1d091 100644 --- a/lib/pleroma/telemetry/logger.ex +++ b/lib/pleroma/telemetry/logger.ex @@ -7,7 +7,8 @@ defmodule Pleroma.Telemetry.Logger do [:pleroma, :connection_pool, :reclaim, :start], [:pleroma, :connection_pool, :reclaim, :stop], [:pleroma, :connection_pool, :provision_failure], - [:pleroma, :connection_pool, :client_death] + [:pleroma, :connection_pool, :client, :dead], + [:pleroma, :connection_pool, :client, :add] ] def attach do :telemetry.attach_many("pleroma-logger", @events, &handle_event/4, []) @@ -62,7 +63,7 @@ def handle_event( end def handle_event( - [:pleroma, :connection_pool, :client_death], + [:pleroma, :connection_pool, :client, :dead], %{client_pid: client_pid, reason: reason}, %{key: key}, _ @@ -73,4 +74,17 @@ def handle_event( }" end) end + + def handle_event( + [:pleroma, :connection_pool, :client, :add], + %{clients: [_, _ | _] = clients}, + %{key: key, protocol: :http}, + _ + ) do + Logger.info(fn -> + "Pool worker for #{key}: #{length(clients)} clients are using an HTTP1 connection at the same time, head-of-line blocking might occur." + end) + end + + def handle_event([:pleroma, :connection_pool, :client, :add], _, _, _), do: :ok end